{
 "cells": [
  {
   "cell_type": "raw",
   "id": "715b3105",
   "metadata": {
    "editable": true,
    "raw_mimetype": "text/restructuredtext",
    "slideshow": {
     "slide_type": ""
    },
    "tags": []
   },
   "source": [
    ".. _logging:\n",
    "\n",
    "Logging\n",
    "=======\n",
    "\n",
    "Because it provides an incredible breadth and depth of functionality for managing program output, Cicada uses Python's builtin :mod:`logging` module to report messages from the library. Thus, you should always initialize Python's logging system at the beginning of a Cicada program, even if you don't plan to use :mod:`logging` yourself:"
   ]
  },
  {
   "cell_type": "code",
   "execution_count": 1,
   "id": "34be8d1c",
   "metadata": {
    "editable": true,
    "slideshow": {
     "slide_type": ""
    },
    "tags": []
   },
   "outputs": [],
   "source": [
    "import logging\n",
    "logging.basicConfig(level=logging.INFO)"
   ]
  },
  {
   "cell_type": "raw",
   "id": "c7f79e21",
   "metadata": {
    "editable": true,
    "raw_mimetype": "text/restructuredtext",
    "slideshow": {
     "slide_type": ""
    },
    "tags": []
   },
   "source": [
    ".. tip::\n",
    "\n",
    "    We strongly recommend that you get to know the Python :mod:`logging` module, which can benefit all of your programming projects!\n",
    "    \n",
    "By default, Cicada is configured to only log warning messages, so you won't see any output during normal operation:"
   ]
  },
  {
   "cell_type": "code",
   "execution_count": 2,
   "id": "512a415d",
   "metadata": {
    "editable": true,
    "slideshow": {
     "slide_type": ""
    },
    "tags": []
   },
   "outputs": [
    {
     "name": "stdout",
     "output_type": "stream",
     "text": [
      "Hello from player 1!Hello from player 0!\n",
      "\n"
     ]
    }
   ],
   "source": [
    "from cicada.communicator import SocketCommunicator\n",
    "\n",
    "def main(communicator):\n",
    "    print(f\"Hello from player {communicator.rank}!\")\n",
    "\n",
    "SocketCommunicator.run(world_size=2, fn=main);"
   ]
  },
  {
   "cell_type": "raw",
   "id": "4367f843",
   "metadata": {
    "raw_mimetype": "text/restructuredtext"
   },
   "source": [
    "If you want greater visibility into what the library is doing (particularly to setup communication), you can adjust log levels accordingly:"
   ]
  },
  {
   "cell_type": "code",
   "execution_count": 3,
   "id": "ca330dee",
   "metadata": {
    "editable": true,
    "slideshow": {
     "slide_type": ""
    },
    "tags": []
   },
   "outputs": [
    {
     "name": "stderr",
     "output_type": "stream",
     "text": [
      "INFO:cicada.communicator.socket.connect:Comm world player 0 listening to tcp://127.0.0.1:65298 for connections.\n",
      "INFO:cicada.communicator.socket.connect:Comm world player 1 listening to tcp://127.0.0.1:65300 for connections.\n",
      "INFO:cicada.communicator.socket.connect:Comm world player 1 direct connect with ['tcp://127.0.0.1:65298', 'tcp://127.0.0.1:65300'].\n",
      "INFO:cicada.communicator.socket.connect:Comm world player 0 direct connect with ['tcp://127.0.0.1:65298', 'tcp://127.0.0.1:65300'].\n",
      "INFO:cicada.communicator.socket.connect:Comm world player 0 tcp://127.0.0.1:65298 accepted connection from tcp://127.0.0.1:65304\n",
      "INFO:cicada.communicator.socket.connect:Comm world player 1 tcp://127.0.0.1:65304 connected to player 0 tcp://127.0.0.1:65298\n",
      "INFO:cicada.communicator.socket:Comm world player 0 communicator ready.\n",
      "INFO:cicada.communicator.socket:Comm world player 1 communicator ready.\n"
     ]
    },
    {
     "name": "stdout",
     "output_type": "stream",
     "text": [
      "Hello from player 0!Hello from player 1!\n",
      "\n"
     ]
    },
    {
     "name": "stderr",
     "output_type": "stream",
     "text": [
      "INFO:cicada.communicator.socket:Comm world player 1 communicator freed.\n",
      "INFO:cicada.communicator.socket:Comm world player 0 communicator freed.\n",
      "INFO:cicada.communicator.socket:Comm world player 0 result: None\n",
      "INFO:cicada.communicator.socket:Comm world player 1 result: None\n"
     ]
    }
   ],
   "source": [
    "logging.getLogger(\"cicada.communicator\").setLevel(logging.INFO)\n",
    "\n",
    "SocketCommunicator.run(world_size=2, fn=main)\n",
    "\n",
    "logging.getLogger(\"cicada.communicator\").setLevel(logging.WARNING) # Put things back the way they were"
   ]
  },
  {
   "cell_type": "raw",
   "id": "4f789a38",
   "metadata": {
    "editable": true,
    "raw_mimetype": "text/restructuredtext",
    "slideshow": {
     "slide_type": ""
    },
    "tags": []
   },
   "source": [
    "Application Logging\n",
    "-------------------\n",
    "\n",
    "For application output from your MPC programs, Cicada provides its own :class:`~cicada.logger.Logger` class, which wraps a standard Python :class:`logging.Logger` and uses a :class:`~cicada.communicator.interface.Communicator` to coordinate player output. \n",
    "\n",
    "When you use Cicada's :class:`~cicada.logger.Logger`, player outputs will appear in rank order without interleaving or stepping on one another (compare the following output with the preceeding examples):"
   ]
  },
  {
   "cell_type": "code",
   "execution_count": 4,
   "id": "70f5337a",
   "metadata": {},
   "outputs": [
    {
     "name": "stderr",
     "output_type": "stream",
     "text": [
      "INFO:root:Hello from player 0!\n",
      "INFO:root:Hello from player 1!\n"
     ]
    }
   ],
   "source": [
    "from cicada.logger import Logger\n",
    "\n",
    "def main(communicator):\n",
    "    log = Logger(logger=logging.getLogger(), communicator=communicator)\n",
    "    log.info(f\"Hello from player {communicator.rank}!\")\n",
    "\n",
    "SocketCommunicator.run(world_size=2, fn=main);"
   ]
  },
  {
   "cell_type": "raw",
   "id": "0dcaa7fb",
   "metadata": {
    "raw_mimetype": "text/restructuredtext"
   },
   "source": [
    "Just like Python's builtin :class:`logging.Logger`, Cicada's :class:`~cicada.logger.Logger` supports higher-priority messages:"
   ]
  },
  {
   "cell_type": "code",
   "execution_count": 5,
   "id": "6a110e4e",
   "metadata": {},
   "outputs": [
    {
     "name": "stderr",
     "output_type": "stream",
     "text": [
      "WARNING:root:Warning message from player 0!\n",
      "WARNING:root:Warning message from player 1!\n"
     ]
    }
   ],
   "source": [
    "def main(communicator):\n",
    "    log = Logger(logger=logging.getLogger(), communicator=communicator)\n",
    "    log.warning(f\"Warning message from player {communicator.rank}!\")\n",
    "\n",
    "SocketCommunicator.run(world_size=2, fn=main);"
   ]
  },
  {
   "cell_type": "code",
   "execution_count": 6,
   "id": "912610f6",
   "metadata": {},
   "outputs": [
    {
     "name": "stderr",
     "output_type": "stream",
     "text": [
      "ERROR:root:Error message from player 0!\n",
      "ERROR:root:Error message from player 1!\n"
     ]
    }
   ],
   "source": [
    "def main(communicator):\n",
    "    log = Logger(logger=logging.getLogger(), communicator=communicator)\n",
    "    log.error(f\"Error message from player {communicator.rank}!\")\n",
    "\n",
    "SocketCommunicator.run(world_size=2, fn=main);"
   ]
  },
  {
   "cell_type": "code",
   "execution_count": 7,
   "id": "8b5cdc4b",
   "metadata": {},
   "outputs": [
    {
     "name": "stderr",
     "output_type": "stream",
     "text": [
      "CRITICAL:root:Critical message from player 0!\n",
      "CRITICAL:root:Critical message from player 1!\n"
     ]
    }
   ],
   "source": [
    "def main(communicator):\n",
    "    log = Logger(logger=logging.getLogger(), communicator=communicator)\n",
    "    log.critical(f\"Critical message from player {communicator.rank}!\")\n",
    "\n",
    "SocketCommunicator.run(world_size=2, fn=main);"
   ]
  },
  {
   "cell_type": "raw",
   "id": "898cab01",
   "metadata": {
    "raw_mimetype": "text/restructuredtext"
   },
   "source": [
    ":class:`~cicada.logger.Logger` also supports lower-priority messages for debugging, but be sure to set the appropriate log level, or you won't see any output:"
   ]
  },
  {
   "cell_type": "code",
   "execution_count": 8,
   "id": "38560091",
   "metadata": {},
   "outputs": [
    {
     "name": "stderr",
     "output_type": "stream",
     "text": [
      "DEBUG:root:Debug message from player 0!\n",
      "DEBUG:root:Debug message from player 1!\n"
     ]
    }
   ],
   "source": [
    "logging.getLogger().setLevel(logging.DEBUG) # Don't filter DEBUG messages\n",
    "\n",
    "def main(communicator):\n",
    "    log = Logger(logger=logging.getLogger(), communicator=communicator)\n",
    "    log.debug(f\"Debug message from player {communicator.rank}!\")\n",
    "\n",
    "SocketCommunicator.run(world_size=2, fn=main);"
   ]
  },
  {
   "cell_type": "raw",
   "id": "6cb1ac87",
   "metadata": {
    "raw_mimetype": "text/restructuredtext"
   },
   "source": [
    "You should keep in mind that :class:`~cicada.logger.Logger` methods are *collective operations* that **must** be called by every player, because they use :ref:`communication-patterns` to coordinate among the players.\n",
    "\n",
    "If you only want to log a message from a single player you can do so, but every player still has to participate in the collective operation:"
   ]
  },
  {
   "cell_type": "code",
   "execution_count": 9,
   "id": "d97af7f4",
   "metadata": {},
   "outputs": [
    {
     "name": "stderr",
     "output_type": "stream",
     "text": [
      "INFO:root:Hello only from player 1!\n"
     ]
    }
   ],
   "source": [
    "def main(communicator):\n",
    "    log = Logger(logger=logging.getLogger(), communicator=communicator)\n",
    "    log.info(f\"Hello only from player {communicator.rank}!\", src=1)\n",
    "\n",
    "SocketCommunicator.run(world_size=5, fn=main);"
   ]
  },
  {
   "cell_type": "raw",
   "id": "00aacd7b",
   "metadata": {
    "raw_mimetype": "text/restructuredtext"
   },
   "source": [
    "You can also limit output to a subset of players:"
   ]
  },
  {
   "cell_type": "code",
   "execution_count": 10,
   "id": "5ef32c30",
   "metadata": {},
   "outputs": [
    {
     "name": "stderr",
     "output_type": "stream",
     "text": [
      "INFO:root:Hello only from player 0!\n",
      "INFO:root:Hello only from player 2!\n",
      "INFO:root:Hello only from player 4!\n"
     ]
    }
   ],
   "source": [
    "def main(communicator):\n",
    "    log = Logger(logger=logging.getLogger(), communicator=communicator)\n",
    "    log.info(f\"Hello only from player {communicator.rank}!\", src=[0, 2, 4])\n",
    "\n",
    "SocketCommunicator.run(world_size=5, fn=main);"
   ]
  },
  {
   "cell_type": "raw",
   "id": "ccb0760c",
   "metadata": {
    "raw_mimetype": "text/restructuredtext"
   },
   "source": [
    "It's important to keep in mind that coordinated logging requires communication among the players at runtime, which can have important ramifications.  As an example, you might not want to use it in a nested loop, where it could seriously impact the performance of an algorithm.\n",
    "\n",
    "Furthermore, coordinated logging is only useful when multiple players are writing to the same console, as is typical when developing and debugging your programs using :meth:`~cicada.communicator.socket.SocketCommunicator.run` or the :ref:`cicada` run command.  Once you're ready to run your program on separate hosts (or in separate terminal sessions on the same host), then the overhead of coordinated logging becomes superflous, since the output is already separated by player.\n",
    "\n",
    "In this case where you're transitioning your progam from development to production, you can disable coordinated logging in a Cicada :class:`~cicada.logger.Logger` at runtime with the `sync` parameter, so that it behaves like a \"normal\" Python :class:`~logging.Logger` with minimal overhead:"
   ]
  },
  {
   "cell_type": "code",
   "execution_count": 11,
   "id": "58c9771f",
   "metadata": {},
   "outputs": [
    {
     "name": "stderr",
     "output_type": "stream",
     "text": [
      "INFO:root:Hello from player 0!\n",
      "INFO:root:Hello from player 1!\n"
     ]
    }
   ],
   "source": [
    "def main(communicator):\n",
    "    log = Logger(logger=logging.getLogger(), communicator=communicator, sync=False)\n",
    "    log.info(f\"Hello from player {communicator.rank}!\")\n",
    "\n",
    "SocketCommunicator.run(world_size=2, fn=main);"
   ]
  },
  {
   "cell_type": "raw",
   "id": "8536d288",
   "metadata": {
    "raw_mimetype": "text/restructuredtext"
   },
   "source": [
    "It's also important to consider that coordinated logging could raise an exception at any time, if a player fails.  Because coordinated logging requires communication among all players, you cannot use it when a failure has occurred - for example, during an error recovery phase or after a communicator has been revoked.\n",
    "\n",
    "Let's see what happens if we try to continue using coordinated logging when a failure has occurred:"
   ]
  },
  {
   "cell_type": "code",
   "execution_count": 12,
   "id": "e66d1d27",
   "metadata": {},
   "outputs": [
    {
     "name": "stderr",
     "output_type": "stream",
     "text": [
      "INFO:root:Player 0 starting ...\n",
      "INFO:root:Player 1 starting ...\n",
      "ERROR:cicada.communicator.socket:Comm world player 1 failed: Timeout('Tag LOGSYNC from player 0 timed-out after 5s')\n"
     ]
    }
   ],
   "source": [
    "def main(communicator):\n",
    "    log = Logger(logger=logging.getLogger(), communicator=communicator)\n",
    "    \n",
    "    try:\n",
    "        log.info(f\"Player {communicator.rank} starting ...\")\n",
    "        \n",
    "        # Wait for a message that never arrives ...\n",
    "        if communicator.rank == 1:\n",
    "            payload = communicator.recv(src=0, tag=42)\n",
    "        \n",
    "    except Exception as e:\n",
    "        log.error(f\"Player {communicator.rank} exception: {e}\")\n",
    "\n",
    "SocketCommunicator.run(world_size=2, fn=main);"
   ]
  },
  {
   "cell_type": "raw",
   "id": "e9532a10",
   "metadata": {
    "raw_mimetype": "text/restructuredtext"
   },
   "source": [
    "In this case, player 1 waits for a message from player 0 that never arrives, because player 0 has already exited.  This raises a Timeout exception (as it should), but player 1 tries to use the logger in the exception handler; this raises a second exception, because the logger is trying to synchronize its output with a nonexistent player!\n",
    "\n",
    "To handle this case correctly, players can (temporarily or permanently) disable synchronization at any time after the logger has been created using the :attr:`~cicada.logger.Logger.sync` property:"
   ]
  },
  {
   "cell_type": "code",
   "execution_count": 13,
   "id": "0b009951",
   "metadata": {},
   "outputs": [
    {
     "name": "stderr",
     "output_type": "stream",
     "text": [
      "INFO:root:Player 0 starting ...\n",
      "INFO:root:Player 1 starting ...\n",
      "ERROR:root:Player 0 exception: Tag 42 from player 1 timed-out after 5s\n"
     ]
    }
   ],
   "source": [
    "def main(communicator):\n",
    "    log = Logger(logger=logging.getLogger(), communicator=communicator)\n",
    "    \n",
    "    try:\n",
    "        log.info(f\"Player {communicator.rank} starting ...\")\n",
    "        \n",
    "        # Wait for a message that will neve arrives\n",
    "        if communicator.rank == 0:\n",
    "            payload = communicator.recv(src=1, tag=42)\n",
    "        \n",
    "    except Exception as e:\n",
    "        log.sync = False # Disable coordinated logging\n",
    "        log.error(f\"Player {communicator.rank} exception: {e}\")\n",
    "\n",
    "SocketCommunicator.run(world_size=2, fn=main);"
   ]
  },
  {
   "cell_type": "raw",
   "id": "acba8b5e",
   "metadata": {
    "editable": true,
    "raw_mimetype": "text/restructuredtext",
    "slideshow": {
     "slide_type": ""
    },
    "tags": []
   },
   "source": [
    "After disabling synchronization it's safe to use the logger in the exception handler, since it no longer tries to communicate with the other players."
   ]
  },
  {
   "cell_type": "raw",
   "id": "0e6ca957-732a-4d5e-9885-96eb2a75910a",
   "metadata": {
    "editable": true,
    "raw_mimetype": "text/restructuredtext",
    "slideshow": {
     "slide_type": ""
    },
    "tags": []
   },
   "source": [
    ".. seealso:: :ref:`transcripts`"
   ]
  }
 ],
 "metadata": {
  "celltoolbar": "Raw Cell Format",
  "kernelspec": {
   "display_name": "Python 3 (ipykernel)",
   "language": "python",
   "name": "python3"
  },
  "language_info": {
   "codemirror_mode": {
    "name": "ipython",
    "version": 3
   },
   "file_extension": ".py",
   "mimetype": "text/x-python",
   "name": "python",
   "nbconvert_exporter": "python",
   "pygments_lexer": "ipython3",
   "version": "3.12.2"
  }
 },
 "nbformat": 4,
 "nbformat_minor": 5
}