{
 "cells": [
  {
   "cell_type": "markdown",
   "id": "7627a6fe",
   "metadata": {},
   "source": [
    "# Logging and Warnings\n",
    "\n",
    "`Parameterized` objects provide methods for displaying logging messages and warnings in a way that can be controlled and redirected globally using the standard Python [logging](https://docs.python.org/3/library/logging.html) module (see the [logging cookbook](https://docs.python.org/3/howto/logging.html)). Compared to using a Python logger directly, using these methods inside your Parameterized class helps users by making the messages consistent, each prepending with information about the Parameterized object where the call was made so that your users can understand what the message indicates.\n",
    "\n",
    "By default, a Python logger named `param` will be instantiated to do the logging, but another logger can be supplied by setting `param.parameterized.logger` to it after importing `param.parameterized`.\n",
    "\n",
    "\n",
    "## Writing log messages\n",
    "\n",
    "Each logging message has an associated logging `level` that indicates how severe a condition is being described (DEBUG, VERBOSE, INFO (aka \"message\"), WARNING, ERROR, or CRITICAL). These levels are as defined by the logging module, except for the addition of VERBOSE as a level intermediate between DEBUG (internal debugging information) and INFO (user-relevant non-error messages).\n",
    "\n",
    "The typical way to print a message is to call `.param.log()` with one of the following logging levels:\n",
    "\n",
    "- `.param.log(param.DEBUG, ...)`: Detailed debugging information, not displayed onscreen by default.\n",
    "- `.param.log(param.VERBOSE, ...)`: Additional sometimes-useful information, not displayed onscreen by default.\n",
    "- `.param.log(param.INFO, ...)`: Informative message, displayed onscreen by default.\n",
    "- `.param.log(param.WARNING, ...)`: Warning of an unexpected or inappropriate but non-fatal condition, displayed onscreen by default.\n",
    "\n",
    "For convenience and to allow eventual integration with the Python [warnings](https://docs.python.org/3/library/warnings.html) module, `.param.warning(` is available as an alias for `.param.log(param.WARNING,`:\n",
    "\n",
    "- `.param.warning(...)`: Warning of an unexpected or inappropriate but non-fatal condition, displayed onscreen by default.\n",
    "\n",
    "The arguments accepted in each case are the same as those of [logging.debug()](https://docs.python.org/3/library/logging.html#logging.debug). Specifically, each call is like `.param.debug(msg, *args, **kw)`, where `msg` is an [old-style ('%') format string](https://wiki.python.org/moin/StringFormatting) and the `args` and `kwargs` will be merged with that format string. E.g.:"
   ]
  },
  {
   "cell_type": "code",
   "execution_count": null,
   "id": "1daef0ad",
   "metadata": {},
   "outputs": [],
   "source": [
    "import param\n",
    "\n",
    "desired = 1\n",
    "actual = 5\n",
    "\n",
    "param.main.param.log(param.INFO, \"Welcome!\")\n",
    "param.main.param.log(param.VERBOSE, \"Local variables: %s\", locals())\n",
    "param.main.param.log(param.WARNING, \"Value %02d is not %d\", actual, desired)\n",
    "param.main.param.warning(\"Value %02d is not %d\", actual, desired)"
   ]
  },
  {
   "cell_type": "markdown",
   "id": "ff2462c4",
   "metadata": {},
   "source": [
    "Here we've used the default global Parameterized object `param.main`, useful for generic module-level messages, but more often you would make a call like `self.param.log()` _inside_ a Parameterized class instead. You can see that the messages are each prefixed by the logging level, `param` (the name of the default logger), and the name of this object (`main` in this case). You can also see that, by default, verbose messages are not actually printed.\n",
    "\n",
    "You may wonder (a) why the formatting string is \"old style\" , and (b) why the formatting values \"actual, desired\" are not combined directly with the formatting string. I.e., why not just use a Python3 f-string, like:"
   ]
  },
  {
   "cell_type": "code",
   "execution_count": null,
   "id": "9f3b2a86",
   "metadata": {},
   "outputs": [],
   "source": [
    "param.main.param.log(param.WARNING, f\"Value {actual:02} is not {desired}\") # Discouraged!"
   ]
  },
  {
   "cell_type": "markdown",
   "id": "4a96c56b",
   "metadata": {},
   "source": [
    "The answer is that particularly for `debug` and `verbose` messages that could occur inside frequently executed code, we want logging to be \"lazy\", in that we do not want to render a string representation for `actual`, `desired`, etc. unless we are actually printing the message. If we use an f-string or any other locally formatted string, the string formatting will be done _whether_ _or_ _not_ the message will be displayed, potentially causing drastic slowdowns in your code. For instance, in the code above, the entire `locals()` dictionary would be iterated over, printed to strings. Of course, since the message isn't being printed in that case, the entire format string would then be discarded, greatly slowing down the code without producing any output. To avoid that, the logging module has to defer the string substitution and handle that itself, and it was written before Python3, so it only supports old-style substitution. So, even though it is more awkward, it is highly recommended to use this old-style, lazy string formatting support."
   ]
  },
  {
   "cell_type": "markdown",
   "id": "aeeda03b",
   "metadata": {},
   "source": [
    "## Controlling the logging level\n",
    "\n",
    "You can use the `param.parameterized.logging_level` context manager to temporarily reduce or elevate the logging level while you execute code:"
   ]
  },
  {
   "cell_type": "code",
   "execution_count": null,
   "id": "f09f288a",
   "metadata": {},
   "outputs": [],
   "source": [
    "with param.logging_level('CRITICAL'):\n",
    "    param.main.param.log(param.INFO, \"Message 1\")\n",
    "    param.main.param.log(param.VERBOSE, \"Verbose 1\")"
   ]
  },
  {
   "cell_type": "code",
   "execution_count": null,
   "id": "85dbe122",
   "metadata": {},
   "outputs": [],
   "source": [
    "with param.logging_level('DEBUG'):\n",
    "    param.main.param.log(param.INFO, \"Message 2\")\n",
    "    param.main.param.log(param.VERBOSE, \"Verbose 2\")"
   ]
  },
  {
   "cell_type": "markdown",
   "id": "3b881898",
   "metadata": {},
   "source": [
    "You can also set the value more globally (and permanently) on the logger object:"
   ]
  },
  {
   "cell_type": "code",
   "execution_count": null,
   "id": "a429ac57",
   "metadata": {},
   "outputs": [],
   "source": [
    "param.get_logger().setLevel(param.DEBUG)"
   ]
  },
  {
   "cell_type": "code",
   "execution_count": null,
   "id": "7afeb934",
   "metadata": {},
   "outputs": [],
   "source": [
    "param.main.param.log(param.INFO, \"Message 2\")\n",
    "param.main.param.log(param.VERBOSE, \"Verbose 2\")"
   ]
  },
  {
   "cell_type": "markdown",
   "id": "4ebe358c",
   "metadata": {},
   "source": [
    "For testing, continuous integration (CI), or other specific applications, you can also set `param.parameterized.warnings_as_exceptions = True`, which will cause your program to raise an exception the first time it encounters any warning."
   ]
  },
  {
   "cell_type": "markdown",
   "id": "54f42ad0",
   "metadata": {},
   "source": [
    "# Controlling the formatting of log messages\n",
    "\n",
    "The Python logging module provides many options for configuring how the log messages are generated. For complete control, you can instantiate your own logger and set `param.parameterized.logger` to it after importing `param.parameterized`.\n",
    "\n",
    "A hook is provided for the relatively common case when you want to prefix each message with the time of day, a progress indication, a simulator time, or some other indication of a global state. Specifically, you can set `param.parameterized.dbprint_prefix` to a callable object returning a string. The object will be called when constructing each message:"
   ]
  },
  {
   "cell_type": "code",
   "execution_count": null,
   "id": "be2a5f2c",
   "metadata": {},
   "outputs": [],
   "source": [
    "from datetime import datetime\n",
    "#param.parameterized.warnings_as_exceptions = True\n",
    "\n",
    "param.parameterized.dbprint_prefix=lambda: str(datetime.now())\n",
    "\n",
    "param.main.param.warning(\"Message 4\")\n",
    "param.main.param.warning(\"Message 5\")"
   ]
  },
  {
   "cell_type": "markdown",
   "id": "e94c2fa9",
   "metadata": {},
   "source": [
    "## Counting warnings\n",
    "\n",
    "Typically, a program will abort if an error is encountered, making such a condition hard to miss, but warning messages might be lost in a sea of informational, verbose, or debug messages. Param keeps track of how many times `.param.warning(...)` (or its alias `.param.log(param.WARNING, ...)`) has been called, and it is often useful to print out that value at the end of a program run:"
   ]
  },
  {
   "cell_type": "code",
   "execution_count": null,
   "id": "348f9d37",
   "metadata": {},
   "outputs": [],
   "source": [
    "print(f\"Run completed. {param.parameterized.warning_count} warnings were encountered.\")"
   ]
  }
 ],
 "metadata": {
  "language_info": {
   "name": "python",
   "pygments_lexer": "ipython3"
  }
 },
 "nbformat": 4,
 "nbformat_minor": 5
}