diff --git a/doc/development/guide/logging.rst b/doc/development/guide/logging.rst index 609107860a4..54f0a0cc349 100644 --- a/doc/development/guide/logging.rst +++ b/doc/development/guide/logging.rst @@ -29,24 +29,36 @@ To add logging support to components of PennyLane, we must define a module logge which will be used within the given module, and track directories, filenames and function names, as we have defined the appropriate types -within the formatter configuration (see :class:`pennylane.logging.DefaultFormatter`). With the logger defined, we can selectively add to the logger by if-else statements, which compare the given module’s log-level to any log record -message it receives. This step is not necessary, as the message will -only output if the level is enabled, though if an expensive function -call is required to build the string for the log-message, it can be -faster to perform this check: +within the formatter configuration (see :class:`pennylane.logging.DefaultFormatter`). With the logger defined, we can selectively add to the logger via two methods: -.. code:: python +#. Using decorators on the required functions and methods in a given module: + + .. code:: python + + # debug_logger can be used to decorate any method or free function + # debug_logger_init can be used to decorate class __init__ methods. + from pennylane.logging import debug_logger, debug_logger_init + + @debug_logger + def my_func(arg1, arg2): + return arg1 + arg2 - if logger.isEnabledFor(logging.DEBUG): - logger.debug( - """Entry with args=(arg_name_1=%s, arg_name_2=%s, ..., arg_name_n=%s)""", - arg_name_1, arg_name_2, ..., arg_name_n, - ) +#. Explicitly by if-else statements, which compare the given module’s log-level to any log record message it receives. This step is not necessary, as the message will + only output if the level is enabled, though if an expensive function + call is required to build the string for the log-message, it can be + faster to perform this check: -The above line can be added below the function/method entry point, -and the provided arguments can be used to populate the log message. This -allows us a way to track the inputs and calls through the stack in the -order they are executed, as is the basis for following a trail of + .. code:: python + + if logger.isEnabledFor(logging.DEBUG): + logger.debug( + """Entry with args=(arg_name_1=%s, arg_name_2=%s, ..., arg_name_n=%s)""", + arg_name_1, arg_name_2, ..., arg_name_n, + ) + +Both versions provide similar functionality, though the explicit logger call allows more custom message-formatting, such as expanding functions as string representation, filtering of data, and other useful processing for a valid record. + +These logging options allow us a way to track the inputs and calls through the stack in the order they are executed, as is the basis for following a trail of execution as needed. All debug log-statements currently added to the PennyLane execution @@ -82,6 +94,8 @@ messages based on some criteria, we can add these to the respective handlers. As an example, we can go through the configuration file and explore the options. +For ease-of-development, the function :func:`pennylane.logging.edit_system_config` opens an editor (if the ``EDITOR`` environment variable is set), or a viewer of the existing file configuration, which can be used to modify the existing options. + Modifying the configuration options ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~ diff --git a/doc/introduction/logging.rst b/doc/introduction/logging.rst index fb46f5cb4b2..a8bf0281992 100644 --- a/doc/introduction/logging.rst +++ b/doc/introduction/logging.rst @@ -29,4 +29,7 @@ outputs to the default configured handler, which is directed to the standard out level = "DEBUG" # Set to TRACE for highest verbosity propagate = false + +Viewing the existing logging configuration file is possible by calling the :func:`pennylane.logging.edit_system_config` function which will open the file in an existing browser or editor window. + For more info on the customization of the logging options, please see the logging development guide at :doc:`/development/guide/logging`, and the `Python logging documentation `_. diff --git a/doc/releases/changelog-dev.md b/doc/releases/changelog-dev.md index 20f1436e2e4..323549d8155 100644 --- a/doc/releases/changelog-dev.md +++ b/doc/releases/changelog-dev.md @@ -9,6 +9,9 @@

Improvements 🛠

+* Logging now allows for an easier opt-in across the stack, and also extends control support to `catalyst`. + [(#5528)](https://github.com/PennyLaneAI/pennylane/pull/5528). + * A number of templates have been updated to be valid pytrees and PennyLane operations. [(#5698)](https://github.com/PennyLaneAI/pennylane/pull/5698) diff --git a/pennylane/devices/default_mixed.py b/pennylane/devices/default_mixed.py index 80661c7faa3..a4a84a19098 100644 --- a/pennylane/devices/default_mixed.py +++ b/pennylane/devices/default_mixed.py @@ -21,6 +21,7 @@ import functools import itertools +import logging from collections import defaultdict from string import ascii_letters as ABC @@ -29,6 +30,7 @@ import pennylane as qml import pennylane.math as qnp from pennylane import BasisState, DeviceError, QubitDensityMatrix, QubitDevice, Snapshot, StatePrep +from pennylane.logging import debug_logger, debug_logger_init from pennylane.measurements import ( CountsMP, DensityMatrixMP, @@ -47,6 +49,9 @@ from .._version import __version__ +logger = logging.getLogger(__name__) +logger.addHandler(logging.NullHandler()) + ABC_ARRAY = np.array(list(ABC)) tolerance = 1e-10 @@ -181,6 +186,7 @@ def _asarray(array, dtype=None): res = qnp.cast(array, dtype=dtype) return res + @debug_logger_init def __init__( self, wires, @@ -252,6 +258,7 @@ def state(self): # User obtains state as a matrix return qnp.reshape(self._pre_rotated_state, (dim, dim)) + @debug_logger def density_matrix(self, wires): """Returns the reduced density matrix over the given wires. @@ -266,12 +273,14 @@ def density_matrix(self, wires): wires = self.map_wires(wires) return qml.math.reduce_dm(state, indices=wires, c_dtype=self.C_DTYPE) + @debug_logger def purity(self, mp, **kwargs): # pylint: disable=unused-argument """Returns the purity of the final state""" state = getattr(self, "state", None) wires = self.map_wires(mp.wires) return qml.math.purity(state, indices=wires, c_dtype=self.C_DTYPE) + @debug_logger def reset(self): """Resets the device""" super().reset() @@ -279,6 +288,7 @@ def reset(self): self._state = self._create_basis_state(0) self._pre_rotated_state = self._state + @debug_logger def analytic_probability(self, wires=None): if self._state is None: return None @@ -706,6 +716,7 @@ def _apply_operation(self, operation): # pylint: disable=arguments-differ + @debug_logger def execute(self, circuit, **kwargs): """Execute a queue of quantum operations on the device and then measure the given observables. @@ -760,6 +771,7 @@ def execute(self, circuit, **kwargs): self.measured_wires = qml.wires.Wires.all_wires(wires_list) return super().execute(circuit, **kwargs) + @debug_logger def apply(self, operations, rotations=None, **kwargs): rotations = rotations or [] diff --git a/pennylane/devices/default_qubit.py b/pennylane/devices/default_qubit.py index 6a1eebd81e1..613f7395646 100644 --- a/pennylane/devices/default_qubit.py +++ b/pennylane/devices/default_qubit.py @@ -16,7 +16,6 @@ """ import concurrent.futures -import inspect import logging from dataclasses import replace from functools import partial @@ -26,6 +25,7 @@ import numpy as np import pennylane as qml +from pennylane.logging import debug_logger, debug_logger_init from pennylane.measurements.mid_measure import MidMeasureMP from pennylane.ops.op_math.condition import Conditional from pennylane.tape import QuantumTape @@ -419,6 +419,7 @@ def reset_prng_key(self): """ # pylint:disable = too-many-arguments + @debug_logger_init def __init__( self, wires=None, @@ -439,6 +440,7 @@ def __init__( self._rng = np.random.default_rng(seed) self._debugger = None + @debug_logger def supports_derivatives( self, execution_config: Optional[ExecutionConfig] = None, @@ -475,6 +477,7 @@ def supports_derivatives( return _supports_adjoint(circuit=circuit) return False + @debug_logger def preprocess( self, execution_config: ExecutionConfig = DefaultExecutionConfig, @@ -566,20 +569,13 @@ def _setup_execution_config(self, execution_config: ExecutionConfig) -> Executio updated_values["device_options"][option] = getattr(self, f"_{option}") return replace(execution_config, **updated_values) + @debug_logger def execute( self, circuits: QuantumTape_or_Batch, execution_config: ExecutionConfig = DefaultExecutionConfig, ) -> Result_or_ResultBatch: self.reset_prng_key() - if logger.isEnabledFor(logging.DEBUG): - logger.debug( - """Entry with args=(circuits=%s) called by=%s""", - circuits, - "::L".join( - str(i) for i in inspect.getouterframes(inspect.currentframe(), 2)[1][1:3] - ), - ) max_workers = execution_config.device_options.get("max_workers", self._max_workers) self._state_cache = {} if execution_config.use_device_jacobian_product else None @@ -618,6 +614,7 @@ def execute( return results + @debug_logger def compute_derivatives( self, circuits: QuantumTape_or_Batch, @@ -637,6 +634,7 @@ def compute_derivatives( return res + @debug_logger def execute_and_compute_derivatives( self, circuits: QuantumTape_or_Batch, @@ -659,6 +657,7 @@ def execute_and_compute_derivatives( return tuple(zip(*results)) + @debug_logger def supports_jvp( self, execution_config: Optional[ExecutionConfig] = None, @@ -678,6 +677,7 @@ def supports_jvp( """ return self.supports_derivatives(execution_config, circuit) + @debug_logger def compute_jvp( self, circuits: QuantumTape_or_Batch, @@ -697,6 +697,7 @@ def compute_jvp( return res + @debug_logger def execute_and_compute_jvp( self, circuits: QuantumTape_or_Batch, @@ -724,6 +725,7 @@ def execute_and_compute_jvp( return tuple(zip(*results)) + @debug_logger def supports_vjp( self, execution_config: Optional[ExecutionConfig] = None, @@ -743,6 +745,7 @@ def supports_vjp( """ return self.supports_derivatives(execution_config, circuit) + @debug_logger def compute_vjp( self, circuits: QuantumTape_or_Batch, @@ -810,6 +813,7 @@ def _state(circuit): return res + @debug_logger def execute_and_compute_vjp( self, circuits: QuantumTape_or_Batch, diff --git a/pennylane/devices/default_qutrit.py b/pennylane/devices/default_qutrit.py index 5e9e346be18..4ac1fe0cbb9 100644 --- a/pennylane/devices/default_qutrit.py +++ b/pennylane/devices/default_qutrit.py @@ -19,16 +19,21 @@ simulation of qutrit-based quantum computing. """ import functools +import logging import numpy as np import pennylane as qml # pylint: disable=unused-import from pennylane import DeviceError, QutritBasisState, QutritDevice from pennylane.devices.default_qubit_legacy import _get_slice +from pennylane.logging import debug_logger, debug_logger_init from pennylane.wires import WireError from .._version import __version__ +logger = logging.getLogger(__name__) +logger.addHandler(logging.NullHandler()) + # tolerance for numerical errors tolerance = 1e-10 @@ -118,6 +123,7 @@ def _asarray(array, dtype=None): res = qml.math.cast(array, dtype=dtype) return res + @debug_logger_init def __init__( self, wires, @@ -165,6 +171,7 @@ def define_wire_map(self, wires): wire_map = zip(wires, consecutive_wires) return dict(wire_map) + @debug_logger def apply(self, operations, rotations=None, **kwargs): # pylint: disable=arguments-differ rotations = rotations or [] @@ -403,6 +410,7 @@ def _create_basis_state(self, index): def state(self): return self._flatten(self._pre_rotated_state) + @debug_logger def density_matrix(self, wires): """Returns the reduced density matrix of a given set of wires. @@ -460,6 +468,7 @@ def _apply_unitary(self, state, mat, wires): inv_perm = np.argsort(perm) # argsort gives inverse permutation return self._transpose(tdot, inv_perm) + @debug_logger def reset(self): """Reset the device""" super().reset() @@ -468,6 +477,7 @@ def reset(self): self._state = self._create_basis_state(0) self._pre_rotated_state = self._state + @debug_logger def analytic_probability(self, wires=None): if self._state is None: return None diff --git a/pennylane/devices/default_qutrit_mixed.py b/pennylane/devices/default_qutrit_mixed.py index 7c264a9d785..0ade57c0c73 100644 --- a/pennylane/devices/default_qutrit_mixed.py +++ b/pennylane/devices/default_qutrit_mixed.py @@ -13,7 +13,6 @@ # limitations under the License. """The default.qutrit.mixed device is PennyLane's standard qutrit simulator for mixed-state computations.""" -import inspect import logging from dataclasses import replace from typing import Callable, Optional, Sequence, Tuple, Union @@ -21,6 +20,7 @@ import numpy as np import pennylane as qml +from pennylane.logging import debug_logger, debug_logger_init from pennylane.ops import _qutrit__channel__ops__ as channels from pennylane.tape import QuantumTape from pennylane.transforms.core import TransformProgram @@ -176,6 +176,7 @@ def name(self): """The name of the device.""" return "default.qutrit.mixed" + @debug_logger_init def __init__( self, wires=None, @@ -192,6 +193,7 @@ def __init__( self._rng = np.random.default_rng(seed) self._debugger = None + @debug_logger def supports_derivatives( self, execution_config: Optional[ExecutionConfig] = None, @@ -238,6 +240,7 @@ def _setup_execution_config(self, execution_config: ExecutionConfig) -> Executio updated_values["device_options"][option] = getattr(self, f"_{option}") return replace(execution_config, **updated_values) + @debug_logger def preprocess( self, execution_config: ExecutionConfig = DefaultExecutionConfig, @@ -283,19 +286,12 @@ def preprocess( return transform_program, config + @debug_logger def execute( self, circuits: QuantumTape_or_Batch, execution_config: ExecutionConfig = DefaultExecutionConfig, ) -> Result_or_ResultBatch: - if logger.isEnabledFor(logging.DEBUG): - logger.debug( - """Entry with args=(circuits=%s) called by=%s""", - circuits, - "::L".join( - str(i) for i in inspect.getouterframes(inspect.currentframe(), 2)[1][1:3] - ), - ) interface = ( execution_config.interface diff --git a/pennylane/devices/qubit/adjoint_jacobian.py b/pennylane/devices/qubit/adjoint_jacobian.py index d5308e55fb6..7f25cb3a858 100644 --- a/pennylane/devices/qubit/adjoint_jacobian.py +++ b/pennylane/devices/qubit/adjoint_jacobian.py @@ -12,12 +12,14 @@ # See the License for the specific language governing permissions and # limitations under the License. """Functions to apply adjoint jacobian differentiation""" +import logging from numbers import Number from typing import Tuple import numpy as np import pennylane as qml +from pennylane.logging import debug_logger from pennylane.operation import operation_derivative from pennylane.tape import QuantumTape @@ -27,6 +29,9 @@ # pylint: disable=protected-access, too-many-branches +logger = logging.getLogger(__name__) +logger.addHandler(logging.NullHandler()) + def _dot_product_real(bra, ket, num_wires): """Helper for calculating the inner product for adjoint differentiation.""" @@ -68,6 +73,7 @@ def _adjoint_jacobian_state(tape: QuantumTape): return tuple(jac.flatten() for jac in jacobian) +@debug_logger def adjoint_jacobian(tape: QuantumTape, state=None): """Implements the adjoint method outlined in `Jones and Gacon `__ to differentiate an input tape. @@ -143,6 +149,7 @@ def adjoint_jacobian(tape: QuantumTape, state=None): return tuple(tuple(np.array(j_) for j_ in j) for j in jac) +@debug_logger def adjoint_jvp(tape: QuantumTape, tangents: Tuple[Number], state=None): """The jacobian vector product used in forward mode calculation of derivatives. @@ -316,6 +323,7 @@ def _get_vjp_bras(tape, cotangents, ket): return bras, batch_size, null_batch_indices +@debug_logger def adjoint_vjp(tape: QuantumTape, cotangents: Tuple[Number], state=None): """The vector jacobian product used in reverse-mode differentiation. diff --git a/pennylane/devices/qubit/simulate.py b/pennylane/devices/qubit/simulate.py index 7218449c625..47e8c85f36d 100644 --- a/pennylane/devices/qubit/simulate.py +++ b/pennylane/devices/qubit/simulate.py @@ -12,6 +12,8 @@ # See the License for the specific language governing permissions and # limitations under the License. """Simulate a quantum script.""" +import logging + # pylint: disable=protected-access from functools import partial from typing import Optional @@ -20,6 +22,7 @@ from numpy.random import default_rng import pennylane as qml +from pennylane.logging import debug_logger from pennylane.measurements import MidMeasureMP from pennylane.typing import Result @@ -28,6 +31,9 @@ from .measure import measure from .sampling import jax_random_split, measure_with_samples +logger = logging.getLogger(__name__) +logger.addHandler(logging.NullHandler()) + INTERFACE_TO_LIKE = { # map interfaces known by autoray to themselves None: None, @@ -107,6 +113,7 @@ def _postselection_postprocess(state, is_state_batched, shots, rng=None, prng_ke return state, shots +@debug_logger def get_final_state(circuit, debugger=None, **execution_kwargs): """ Get the final state that results from executing the given quantum script. @@ -175,6 +182,7 @@ def get_final_state(circuit, debugger=None, **execution_kwargs): # pylint: disable=too-many-arguments +@debug_logger def measure_final_state(circuit, state, is_state_batched, **execution_kwargs) -> Result: """ Perform the measurements required by the circuit on the provided state. @@ -238,6 +246,7 @@ def measure_final_state(circuit, state, is_state_batched, **execution_kwargs) -> return results +@debug_logger def simulate( circuit: qml.tape.QuantumScript, debugger=None, @@ -316,6 +325,7 @@ def simulate_partial(k): return measure_final_state(circuit, state, is_state_batched, rng=rng, prng_key=meas_key) +@debug_logger def simulate_one_shot_native_mcm( circuit: qml.tape.QuantumScript, debugger=None, **execution_kwargs ) -> Result: diff --git a/pennylane/logging/__init__.py b/pennylane/logging/__init__.py index b036d69d66b..f670be47e19 100644 --- a/pennylane/logging/__init__.py +++ b/pennylane/logging/__init__.py @@ -13,6 +13,8 @@ # limitations under the License. """This module enables support for log-level messaging throughout PennyLane, following the native Python logging framework interface. Please see the :doc:`PennyLane logging development guidelines`, and the official Python documentation for details on usage https://docs.python.org/3/library/logging.html""" -from .configuration import TRACE, config_path, enable_logging +from .configuration import TRACE, config_path, edit_system_config, enable_logging +from .decorators import debug_logger, debug_logger_init from .filter import DebugOnlyFilter, LocalProcessFilter from .formatters.formatter import DefaultFormatter, SimpleFormatter +from .utils import _add_logging_all diff --git a/pennylane/logging/configuration.py b/pennylane/logging/configuration.py index 8826146e669..c78ce01beb9 100644 --- a/pennylane/logging/configuration.py +++ b/pennylane/logging/configuration.py @@ -17,8 +17,11 @@ import logging import logging.config import os +import platform +import subprocess from importlib import import_module from importlib.util import find_spec +from typing import Optional has_toml = False toml_libs = ["tomllib", "tomli", "tomlkit"] @@ -53,10 +56,15 @@ def trace(self, message, *args, **kws): lc.trace = trace -def _configure_logging(config_file): +def _configure_logging(config_file: str, config_override: Optional[dict] = None): """ This method allows custom logging configuration throughout PennyLane. - All configurations are read through the ``log_config.toml`` file. + All configurations are read through the ``log_config.toml`` file, with additional custom options provided through the ``config_override`` dictionary. + + Args: + config_file (str): The path to a given log configuration file, parsed as TOML and adhering to the ``logging.config.dictConfig`` end-point. + + config_override (Optional[dict]): A dictionary with keys-values that override the default configuration options in the given ``config_file`` TOML. """ if not has_toml: raise ImportError( @@ -68,21 +76,27 @@ def _configure_logging(config_file): ) with open(os.path.join(_path, config_file), "rb") as f: pl_config = tomllib.load(f) - logging.config.dictConfig(pl_config) + if not config_override: + logging.config.dictConfig(pl_config) + else: + logging.config.dictConfig({**pl_config, **config_override}) -def enable_logging(): +def enable_logging(config_file: str = "log_config.toml"): """ This method allows to selectively enable logging throughout PennyLane, following the configuration options defined in the ``log_config.toml`` file. Enabling logging through this method will override any externally defined logging configurations. + Args: + config_file (str): The path to a given log configuration file, parsed as TOML and adhering to the ``logging.config.dictConfig`` end-point. The default argument uses the PennyLane ecosystem log-file configuration, located at the directory returned from :func:`pennylane.logging.config_path`. + **Example** >>> qml.logging.enable_logging() """ _add_trace_level() - _configure_logging("log_config.toml") + _configure_logging(config_file) def config_path(): @@ -99,3 +113,43 @@ def config_path(): """ path = os.path.join(_path, "log_config.toml") return path + + +def show_system_config(): + """ + This function opens the logging configuration file in the system-default browser. + """ + # pylint:disable = import-outside-toplevel + import webbrowser + + webbrowser.open(config_path()) + + +def edit_system_config(wait_on_close=False): + """ + This function opens the log configuration file using OS-specific editors. + + Setting the ``EDITOR`` environment variable will override ``xdg-open/open`` on + Linux and MacOS, and allows use of ``wait_on_close`` for editor close before + continuing execution. + + .. warning:: + + As each OS configuration differs user-to-user, you may wish to + instead open this file manually with the ``config_path()`` provided path. + """ + if editor := os.getenv("EDITOR"): + # pylint:disable = consider-using-with + with subprocess.Popen((editor, config_path())) as p: + if wait_on_close: # Only valid when editor is known + p.wait() + # pylint:disable = superfluous-parens + elif (s := platform.system()) in ["Linux", "Darwin"]: + f_cmd = None + if s == "Linux": + f_cmd = "xdg-open" + else: + f_cmd = "open" + subprocess.Popen((f_cmd, config_path())) + else: # Windows-only, does not exist on MacOS/Linux + os.startfile(config_path()) # pylint:disable = no-member diff --git a/pennylane/logging/decorators.py b/pennylane/logging/decorators.py new file mode 100644 index 00000000000..66a9a104efa --- /dev/null +++ b/pennylane/logging/decorators.py @@ -0,0 +1,82 @@ +# Copyright 2018-2024 Xanadu Quantum Technologies Inc. + +# Licensed under the Apache License, Version 2.0 (the "License"); +# you may not use this file except in compliance with the License. +# You may obtain a copy of the License at + +# http://www.apache.org/licenses/LICENSE-2.0 + +# Unless required by applicable law or agreed to in writing, software +# distributed under the License is distributed on an "AS IS" BASIS, +# WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. +# See the License for the specific language governing permissions and +# limitations under the License. +"""This file expands the PennyLane logging functionality to allow additions for function entry and exit logging via decorators.""" + +import inspect +import logging +from functools import partial, wraps + +# Stack level allows moving up the stack with the log records, and prevents +# the decorator function names appearing in the resulting messages. +_debug_log_kwargs = {"stacklevel": 2} + + +def log_string_debug_func(func, log_level, use_entry, override=None): + """ + This decorator utility generates a string containing the called function, the passed arguments, and the source of the function call. + """ + lgr = logging.getLogger(func.__module__) + + def _get_bound_signature(*args, **kwargs) -> str: + s = inspect.signature(func) + # pylint:disable = broad-except + try: + ba = s.bind(*args, **kwargs) + except Exception as e: + # If kwargs are concat onto args, attempt to unpack. Fail otherwise + if len(args) == 2 and len(kwargs) == 0 and isinstance(args[1], dict): + ba = s.bind(*args[0], **args[1]) + else: + raise e + ba.apply_defaults() + if override and len(override): + for k, v in override.keys(): + ba[k] = v + + f_string = str(ba).replace("BoundArguments ", func.__name__) + return f_string + + @wraps(func) + def wrapper_entry(*args, **kwargs): + if lgr.isEnabledFor(log_level): # pragma: no cover + f_string = _get_bound_signature(*args, **kwargs) + s_caller = "::L".join( + [str(i) for i in inspect.getouterframes(inspect.currentframe(), 2)[1][1:3]] + ) + lgr.debug( + f"Calling {f_string} from {s_caller}", + **_debug_log_kwargs, + ) + return func(*args, **kwargs) + + @wraps(func) + def wrapper_exit(*args, **kwargs): + output = func(*args, **kwargs) + if lgr.isEnabledFor(log_level): # pragma: no cover + f_string = _get_bound_signature(*args, **kwargs) + s_caller = "::L".join( + [str(i) for i in inspect.getouterframes(inspect.currentframe(), 2)[1][1:3]] + ) + lgr.debug( + f"Calling {f_string}={output} from {s_caller}", + **{"stacklevel": 2}, + ) + return output + + return wrapper_entry if use_entry else wrapper_exit + + +# For ease-of-use ``debug_logger`` is provided for decoration of public methods and free functions, with ``debug_logger_init`` provided for use with class constructors. +debug_logger = partial(log_string_debug_func, log_level=logging.DEBUG, use_entry=True) +debug_logger_init = partial(log_string_debug_func, log_level=logging.DEBUG, use_entry=False) diff --git a/pennylane/logging/formatters/__init__.py b/pennylane/logging/formatters/__init__.py index 33297d98677..ed35942b601 100644 --- a/pennylane/logging/formatters/__init__.py +++ b/pennylane/logging/formatters/__init__.py @@ -12,4 +12,4 @@ # See the License for the specific language governing permissions and # limitations under the License. """This module defines formatting rules for the PennyLane loggers.""" -from .formatter import DefaultFormatter, SimpleFormatter +from .formatter import DefaultFormatter, DynamicFormatter, SimpleFormatter diff --git a/pennylane/logging/formatters/formatter.py b/pennylane/logging/formatters/formatter.py index e3a6e9893c7..09daa5e9570 100644 --- a/pennylane/logging/formatters/formatter.py +++ b/pennylane/logging/formatters/formatter.py @@ -12,6 +12,7 @@ # See the License for the specific language governing permissions and # limitations under the License. """The PennyLane log-level formatters are defined here with default options, and ANSI-terminal color-codes.""" +import inspect import logging from logging import Formatter from typing import NamedTuple, Tuple, Union @@ -77,7 +78,7 @@ def bash_ansi_codes(): class DefaultFormatter(Formatter): """This formatter has the default rules used for formatting PennyLane log messages.""" - fmt_str = '[%(asctime)s][%(levelname)s][] - %(name)s.%(funcName)s()::"%(message)s"' + fmt_str = '[%(asctime)s][%(levelname)s][] - %(name)s.%(funcName)s::"%(message)s"\n' # 0x000000 Background _text_bg = (0, 0, 0) @@ -114,6 +115,55 @@ def format(self, record): return formatter.format(record) +class DynamicFormatter(Formatter): + """This formatter has the default rules used for formatting PennyLane log messages, with a dynamically updated log format rule""" + + # 0x000000 Background + _text_bg = (0, 0, 0) + + cmap = ColorScheme( + debug=(220, 238, 200), # Grey 1 + debug_bg=_text_bg, + info=(80, 125, 125), # Blue + info_bg=_text_bg, + warning=(208, 167, 133), # Orange + warning_bg=_text_bg, + error=(208, 133, 133), # Red 1 + error_bg=_text_bg, + critical=(135, 53, 53), # Red 2 + critical_bg=(210, 210, 210), # Grey 2 + use_rgb=True, + ) + + @staticmethod + def _build_formats(fmt_str): + cmap = DynamicFormatter.cmap + local_formats = { + logging.DEBUG: build_code_rgb(cmap.debug, cmap.debug_bg) + fmt_str + _ANSI_CODES["end"], + logging.INFO: build_code_rgb(cmap.info, cmap.info_bg) + fmt_str + _ANSI_CODES["end"], + logging.WARNING: build_code_rgb(cmap.warning, cmap.warning_bg) + + fmt_str + + _ANSI_CODES["end"], + logging.ERROR: build_code_rgb(cmap.error, cmap.error_bg) + fmt_str + _ANSI_CODES["end"], + logging.CRITICAL: build_code_rgb(cmap.critical, cmap.critical_bg) + + fmt_str + + _ANSI_CODES["end"], + } + + return local_formats + + def format(self, record): + f = inspect.getouterframes(inspect.currentframe())[ + 8 + ] # Stack depth from log-func call to format function + + fmt_str = f'[%(asctime)s][%(levelname)s][] - %(name)s.{f.function}()::"%(message)s"' + + log_fmt = self._build_formats(fmt_str).get(record.levelno) + formatter = logging.Formatter(log_fmt) + return formatter.format(record) + + class SimpleFormatter(Formatter): """This formatter has a simplified layout and rules used for formatting PennyLane log messages.""" diff --git a/pennylane/logging/log_config.toml b/pennylane/logging/log_config.toml index 25f3b980e3f..dc8fcec97f2 100644 --- a/pennylane/logging/log_config.toml +++ b/pennylane/logging/log_config.toml @@ -13,6 +13,9 @@ version = 1 [formatters.qml_default_formatter] "()" = "pennylane.logging.formatters.formatter.DefaultFormatter" +[formatters.qml_dynamic_formatter] +"()" = "pennylane.logging.formatters.formatter.DynamicFormatter" + [formatters.qml_alt_formatter] "()" = "pennylane.logging.formatters.formatter.SimpleFormatter" @@ -46,12 +49,24 @@ formatter = "qml_default_formatter" level = "DEBUG" stream = "ext://sys.stdout" +[handlers.qml_debug_stream_dyn] +class = "logging.StreamHandler" +formatter = "qml_dynamic_formatter" +level = "DEBUG" +stream = "ext://sys.stdout" + [handlers.qml_debug_stream_alt] class = "logging.StreamHandler" formatter = "qml_alt_formatter" level = "DEBUG" stream = "ext://sys.stdout" +[handlers.qml_debug_syslog] +class = "logging.handlers.SysLogHandler" +formatter = "local_standard" +level = "DEBUG" +address = "/dev/log" + [handlers.qml_debug_file] class = "logging.handlers.RotatingFileHandler" formatter = "local_standard" @@ -80,6 +95,12 @@ handlers = ["qml_debug_stream",] level = "WARN" propagate = false +# Control JAXlib logging +[loggers.jaxlib] +handlers = ["qml_debug_stream",] +level = "WARN" +propagate = false + # Control logging across pennylane [loggers.pennylane] handlers = ["qml_debug_stream",] @@ -93,4 +114,10 @@ handlers = ["qml_debug_stream",] level = "DEBUG" # Set to TRACE for highest verbosity propagate = false +# Control logging across catalyst +[loggers.catalyst] +handlers = ["qml_debug_stream",] +level = "DEBUG" # Set to TRACE for highest verbosity +propagate = false + ############################################################################### diff --git a/pennylane/logging/utils.py b/pennylane/logging/utils.py new file mode 100644 index 00000000000..e8da7b0b117 --- /dev/null +++ b/pennylane/logging/utils.py @@ -0,0 +1,38 @@ +# Copyright 2018-2024 Xanadu Quantum Technologies Inc. + +# Licensed under the Apache License, Version 2.0 (the "License"); +# you may not use this file except in compliance with the License. +# You may obtain a copy of the License at + +# http://www.apache.org/licenses/LICENSE-2.0 + +# Unless required by applicable law or agreed to in writing, software +# distributed under the License is distributed on an "AS IS" BASIS, +# WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. +# See the License for the specific language governing permissions and +# limitations under the License. +"""This file provides developer-facing functionality for the PennyLane logging module.""" +import inspect +import sys + +from .decorators import debug_logger + + +def _is_local_fn(f, mod_name): + """ + Predicate that validates if argument ``f`` is a local function belonging to module ``mod_name``. + """ + is_func = inspect.isfunction(f) + is_local_to_mod = inspect.getmodule(f).__name__ == mod_name + return is_func and is_local_to_mod + + +def _add_logging_all(mod_name): + """ + Modifies the module ``mod_name`` to add logging implicitly to all free-functions. + """ + l_func = inspect.getmembers( + sys.modules[mod_name], predicate=lambda x: _is_local_fn(x, mod_name) + ) + for f_name, f in l_func: + globals()[f_name] = debug_logger(f) diff --git a/pennylane/workflow/qnode.py b/pennylane/workflow/qnode.py index 513abd88e83..57d6e89c28b 100644 --- a/pennylane/workflow/qnode.py +++ b/pennylane/workflow/qnode.py @@ -25,6 +25,7 @@ import pennylane as qml from pennylane import Device +from pennylane.logging import debug_logger from pennylane.measurements import CountsMP, MidMeasureMP, Shots from pennylane.tape import QuantumScript, QuantumTape @@ -577,6 +578,7 @@ def transform_program(self): """The transform program used by the QNode.""" return self._transform_program + @debug_logger def add_transform(self, transform_container): """Add a transform (container) to the transform program. @@ -601,7 +603,7 @@ def _update_gradient_fn(self, shots=None, tape=None): ): diff_method = "parameter-shift" - self.gradient_fn, self.gradient_kwargs, self.device = self.get_gradient_fn( + self.gradient_fn, self.gradient_kwargs, self.device = QNode.get_gradient_fn( self._original_device, self.interface, diff_method, tape=tape ) self.gradient_kwargs.update(self._user_gradient_kwargs or {}) @@ -625,6 +627,7 @@ def _update_original_device(self): # pylint: disable=too-many-return-statements @staticmethod + @debug_logger def get_gradient_fn( device, interface, diff_method="best", tape: Optional["qml.tape.QuantumTape"] = None ): @@ -696,6 +699,7 @@ def get_gradient_fn( ) @staticmethod + @debug_logger def get_best_method(device, interface, tape=None): """Returns the 'best' differentiation method for a particular device and interface combination. @@ -742,6 +746,7 @@ def get_best_method(device, interface, tape=None): return qml.gradients.finite_diff, {}, device @staticmethod + @debug_logger def best_method_str(device, interface): """Similar to :meth:`~.get_best_method`, except return the 'best' differentiation method in human-readable format. @@ -780,6 +785,7 @@ def best_method_str(device, interface): return transform @staticmethod + @debug_logger def _validate_backprop_method(device, interface, tape=None): if isinstance(device, qml.devices.Device): raise ValueError( @@ -912,6 +918,7 @@ def tape(self) -> QuantumTape: qtape = tape # for backwards compatibility + @debug_logger def construct(self, args, kwargs): # pylint: disable=too-many-branches """Call the quantum function with a tape context, ensuring the operations get queued.""" kwargs = copy.copy(kwargs) diff --git a/tests/conftest.py b/tests/conftest.py index 8f8cf90cc8a..1b90d1f20f5 100644 --- a/tests/conftest.py +++ b/tests/conftest.py @@ -15,6 +15,7 @@ Pytest configuration file for PennyLane test suite. """ # pylint: disable=unused-import +import contextlib import os import pathlib diff --git a/tests/devices/qutrit_mixed/test_qutrit_mixed_tracking.py b/tests/devices/qutrit_mixed/test_qutrit_mixed_tracking.py index 8312e5d0fef..a735157784f 100644 --- a/tests/devices/qutrit_mixed/test_qutrit_mixed_tracking.py +++ b/tests/devices/qutrit_mixed/test_qutrit_mixed_tracking.py @@ -14,8 +14,6 @@ """ Tests for the tracking capabilities of default qutrit mixed. """ -import logging - import numpy as np import pytest @@ -222,48 +220,3 @@ def test_multiple_expval_with_prods(self): assert dev.tracker.totals["executions"] == expected_exec assert dev.tracker.totals["simulations"] == 1 assert dev.tracker.totals["shots"] == expected_shots - - -@pytest.mark.logging -def test_execution_debugging(caplog): - """Test logging of QNode forward pass from default qutrit mixed.""" - - qml.logging.enable_logging() - - pl_logger = logging.root.manager.loggerDict["pennylane"] - plqn_logger = logging.root.manager.loggerDict["pennylane.qnode"] - - # Ensure logs messages are propagated for pytest capture - pl_logger.propagate = True - plqn_logger.propagate = True - - with caplog.at_level(logging.DEBUG): - dev = qml.device("default.qutrit.mixed", wires=2) - params = qml.numpy.array(0.1234) - - @qml.qnode(dev, diff_method=None) - def circuit(params): - qml.TRX(params, wires=0) - return qml.expval(qml.GellMann(0, 3)) - - circuit(params) - - assert len(caplog.records) == 3 - - log_records_expected = [ - ( - "pennylane.workflow.qnode", - ["Creating QNode(func=