logging_talk.ipynb

{
 "cells": [
  {
   "cell_type": "markdown",
   "metadata": {
    "slideshow": {
     "slide_type": "slide"
    }
   },
   "source": [
    "# Pasaron cosas: logging efectivo para saber qué sucedió\n",
    "\n",
    "\n",
    "<br>\n",
    "<br>\n",
    "<br>\n",
    "<center><img src=\"https://emojipedia-us.s3.dualstack.us-west-1.amazonaws.com/thumbs/120/whatsapp/238/man-shrugging-type-1-2_1f937-1f3fb-200d-2642-fe0f.png\" /> </center>\n",
    "\n",
    "\n",
    "<br>\n",
    "<br>\n",
    "<br>\n",
    "\n",
    "<center><h3> PyConAr 2020</h3></center>\n",
    "\n",
    "<center>Martín Gaitán |  @tin_nqn_</center>"
   ]
  },
  {
   "cell_type": "markdown",
   "metadata": {
    "slideshow": {
     "slide_type": "slide"
    }
   },
   "source": [
    "## Sobre mí\n",
    "\n",
    "- Python, locro y paternidad\n",
    "- Soy ingeniero y docente, laburo en ShipHero\n",
    "- Vivo en Anisacate, Córdoba\n",
    "- Me llevo bien con mis hermanos\n",
    "\n",
    "![image](https://user-images.githubusercontent.com/2355719/97139283-edca5600-1738-11eb-8238-3c6b030092ae.png)\n"
   ]
  },
  {
   "cell_type": "markdown",
   "metadata": {
    "slideshow": {
     "slide_type": "slide"
    }
   },
   "source": [
    "## Agenda\n",
    "\n",
    "- ¿Para qué loggear?\n",
    "- Logging 101\n",
    "- Structlog\n",
    "- Buenas prácticas\n"
   ]
  },
  {
   "cell_type": "markdown",
   "metadata": {
    "slideshow": {
     "slide_type": "slide"
    }
   },
   "source": [
    "## ¿Logging? ¿Para qué?\n",
    "\n",
    "- Planificar en el presente para tener, en el futuro, información útil de ejecuciones (pasadas).\n",
    "- Nos permiten debuggear un problema específico, obtener información de uso, trazabilidad, etc.  \n",
    "- Y también cuantificar para priorizar tareas"
   ]
  },
  {
   "cell_type": "markdown",
   "metadata": {
    "slideshow": {
     "slide_type": "slide"
    }
   },
   "source": [
    "## Logging 101"
   ]
  },
  {
   "cell_type": "markdown",
   "metadata": {
    "slideshow": {
     "slide_type": "fragment"
    }
   },
   "source": [
    "- Logger: expone la interfaz que se usa desde nuestro código. "
   ]
  },
  {
   "cell_type": "markdown",
   "metadata": {
    "slideshow": {
     "slide_type": "fragment"
    }
   },
   "source": [
    "- Handler: envía los *log records* (registros) (creados desde loggers) al destino apropiado (stdout, archivo, red, etc.)  "
   ]
  },
  {
   "cell_type": "markdown",
   "metadata": {
    "slideshow": {
     "slide_type": "fragment"
    }
   },
   "source": [
    "- Filter: excluye o transforma registros."
   ]
  },
  {
   "cell_type": "markdown",
   "metadata": {
    "slideshow": {
     "slide_type": "fragment"
    }
   },
   "source": [
    "- Formatter: plantilla para la representación de salida de los registros. "
   ]
  },
  {
   "cell_type": "markdown",
   "metadata": {
    "slideshow": {
     "slide_type": "subslide"
    }
   },
   "source": [
    "<center>\n",
    "<img width=\"445\" heigth=\"267\" src=\"https://user-images.githubusercontent.com/2355719/91468196-07017400-e868-11ea-9af8-f99f112e8ac8.png\">\n",
    "</center>"
   ]
  },
  {
   "cell_type": "markdown",
   "metadata": {
    "slideshow": {
     "slide_type": "notes"
    }
   },
   "source": [
    "Notas: \n",
    "\n",
    "- Los *logger* son instancias de `logging.Logger`. Se instancian via `logging.getLogger()` \n",
    "- Un *logger* puede tener varios *handlers* y *filters* asociados. \n",
    "- Cada *handler* también puede tener su propio nivel y filtros. \n",
    "- Un *formatter* está relacionado sólo con un *handler*"
   ]
  },
  {
   "cell_type": "markdown",
   "metadata": {
    "slideshow": {
     "slide_type": "slide"
    }
   },
   "source": [
    "\n",
    "![](https://i.imgflip.com/4js04z.jpg)\n"
   ]
  },
  {
   "cell_type": "markdown",
   "metadata": {
    "slideshow": {
     "slide_type": "subslide"
    }
   },
   "source": [
    "Cada registros,  los loggers y los handlers tiene asociado un **nivel de severidad**,\n",
    "\n",
    "![](https://user-images.githubusercontent.com/2355719/91371176-a8e07c80-e7e6-11ea-8773-0674f2e7a943.png)\n"
   ]
  },
  {
   "cell_type": "markdown",
   "metadata": {},
   "source": [
    "Existe un método que emite registros con su respectivo nivel `logger.debug(), logger.info()... `"
   ]
  },
  {
   "cell_type": "markdown",
   "metadata": {
    "slideshow": {
     "slide_type": "subslide"
    }
   },
   "source": [
    "Y los logger tienen un **nivel efectivo** necesario. \n"
   ]
  },
  {
   "cell_type": "code",
   "execution_count": 1,
   "metadata": {},
   "outputs": [],
   "source": [
    "import logging"
   ]
  },
  {
   "cell_type": "code",
   "execution_count": 2,
   "metadata": {},
   "outputs": [
    {
     "data": {
      "text/plain": [
       "<RootLogger root (WARNING)>"
      ]
     },
     "execution_count": 2,
     "metadata": {},
     "output_type": "execute_result"
    }
   ],
   "source": [
    "root = logging.getLogger()    \n",
    "root"
   ]
  },
  {
   "cell_type": "markdown",
   "metadata": {},
   "source": [
    "El logger por defecto \"root\" tiene nivel mínimo `WARNING`"
   ]
  },
  {
   "cell_type": "code",
   "execution_count": 3,
   "metadata": {},
   "outputs": [],
   "source": [
    "root.info(\"Hola PyConAr\")     # info < warning => ignorado"
   ]
  },
  {
   "cell_type": "code",
   "execution_count": 4,
   "metadata": {
    "slideshow": {
     "slide_type": "fragment"
    }
   },
   "outputs": [
    {
     "name": "stderr",
     "output_type": "stream",
     "text": [
      "Dije hola PyConAr!\n"
     ]
    }
   ],
   "source": [
    "root.warning(\"Dije hola PyConAr!\")"
   ]
  },
  {
   "cell_type": "markdown",
   "metadata": {
    "slideshow": {
     "slide_type": "subslide"
    }
   },
   "source": [
    "Pero también los **Handler** tienen nivel"
   ]
  },
  {
   "cell_type": "code",
   "execution_count": 5,
   "metadata": {},
   "outputs": [],
   "source": [
    "otro_logger = logging.getLogger(\"ejemplo\")    \n",
    "otro_logger.setLevel(logging.INFO)     # nivel del logger\n",
    "\n",
    "sh = logging.StreamHandler()\n",
    "sh.setLevel(logging.WARNING)           # nivel del handler\n",
    "\n",
    "otro_logger.addHandler(sh)"
   ]
  },
  {
   "cell_type": "code",
   "execution_count": 7,
   "metadata": {
    "slideshow": {
     "slide_type": "subslide"
    }
   },
   "outputs": [],
   "source": [
    "# alcanza el nivel del logger pero no el del handler\n",
    "otro_logger.info(\"Te la debo, no estoy en tema\")    # el registro se crea, pero no se maneja en el handler  "
   ]
  },
  {
   "cell_type": "code",
   "execution_count": 8,
   "metadata": {},
   "outputs": [
    {
     "name": "stderr",
     "output_type": "stream",
     "text": [
      "veniamos bien, pero pasaron cosas\n"
     ]
    }
   ],
   "source": [
    "otro_logger.warning(\"veniamos bien, pero pasaron cosas\")"
   ]
  },
  {
   "cell_type": "markdown",
   "metadata": {
    "slideshow": {
     "slide_type": "subslide"
    }
   },
   "source": [
    "Recordemos que un logger puede tener **varios handlers**"
   ]
  },
  {
   "cell_type": "code",
   "execution_count": 9,
   "metadata": {},
   "outputs": [],
   "source": [
    "fh = logging.FileHandler('charla.log')\n",
    "fh.setLevel(logging.INFO)\n",
    "\n",
    "# le agregamos este nuevo Handler al logger que ya teniamos\n",
    "otro_logger.addHandler(fh)"
   ]
  },
  {
   "cell_type": "code",
   "execution_count": 10,
   "metadata": {},
   "outputs": [],
   "source": [
    "# esto no va a stdout pero sí al archivo\n",
    "otro_logger.info(\"deberían tener angustia de tomar la decisión, querido Rey, de separarse de España\")"
   ]
  },
  {
   "cell_type": "code",
   "execution_count": 11,
   "metadata": {},
   "outputs": [
    {
     "name": "stdout",
     "output_type": "stream",
     "text": [
      "deberían tener angustia de tomar la decisión, querido Rey, de separarse de España\r\n"
     ]
    }
   ],
   "source": [
    "!cat charla.log"
   ]
  },
  {
   "cell_type": "markdown",
   "metadata": {
    "slideshow": {
     "slide_type": "subslide"
    }
   },
   "source": [
    "### Nombres y propagación\n",
    "\n",
    "- Cuando instanciamos un logger con `getLogger` podemos darle un nombre \n",
    "- El nombre determina el *namespace* (separado por puntos). \n",
    "- Logs loggers \"hijos\" heredan la configuración (y pueden sobrecargarla)\n",
    "\n",
    "La convención es usar la jerarquía completa del módulo\n",
    "\n",
    "```python\n",
    "logger = logging.getLogger(__name__)\n",
    "```"
   ]
  },
  {
   "cell_type": "code",
   "execution_count": 12,
   "metadata": {
    "slideshow": {
     "slide_type": "subslide"
    }
   },
   "outputs": [],
   "source": [
    "# reusamos la config del namespace \"ejemplo\" que tenia `otro_logger`\n",
    "\n",
    "logger = logging.getLogger('ejemplo.hijo')     \n",
    "logger.info(\"Hay lugares donde falta el agua, y lugares donde sobra\")   "
   ]
  },
  {
   "cell_type": "code",
   "execution_count": 13,
   "metadata": {
    "slideshow": {
     "slide_type": "subslide"
    }
   },
   "outputs": [
    {
     "name": "stdout",
     "output_type": "stream",
     "text": [
      "deberían tener angustia de tomar la decisión, querido Rey, de separarse de España\r\n",
      "Hay lugares donde falta el agua, y lugares donde sobra\r\n"
     ]
    }
   ],
   "source": [
    "!cat charla.log"
   ]
  },
  {
   "cell_type": "markdown",
   "metadata": {
    "slideshow": {
     "slide_type": "fragment"
    }
   },
   "source": [
    "`propagate=True` pasa el registro a \"loggers padres\". "
   ]
  },
  {
   "cell_type": "markdown",
   "metadata": {
    "slideshow": {
     "slide_type": "slide"
    }
   },
   "source": [
    "## Filtros\n",
    "\n",
    "Transformar o descartar registros"
   ]
  },
  {
   "cell_type": "code",
   "execution_count": 14,
   "metadata": {},
   "outputs": [],
   "source": [
    "class ShortMsgFilter(logging.Filter):\n",
    "\n",
    "    def filter(self, record):\n",
    "        msg = record.msg\n",
    "        if isinstance(msg, str):\n",
    "            return len(msg) > 10\n",
    "        return False\n",
    "    \n",
    "logger.addFilter(ShortMsgFilter())\n",
    "logger.warning(\"hola\")"
   ]
  },
  {
   "cell_type": "code",
   "execution_count": 15,
   "metadata": {},
   "outputs": [
    {
     "name": "stderr",
     "output_type": "stream",
     "text": [
      "buscaremos otros jueces que nos representen\n"
     ]
    }
   ],
   "source": [
    "logger.warning(\"buscaremos otros jueces que nos representen\")"
   ]
  },
  {
   "cell_type": "markdown",
   "metadata": {
    "slideshow": {
     "slide_type": "slide"
    }
   },
   "source": [
    "## ¿Cómo configuramos? \n",
    "\n",
    "![](https://i.imgflip.com/4ju4ym.jpg)\n"
   ]
  },
  {
   "cell_type": "code",
   "execution_count": 1,
   "metadata": {
    "slideshow": {
     "slide_type": "subslide"
    }
   },
   "outputs": [],
   "source": [
    "import logging.config\n",
    "\n",
    "DEFAULT_LOGGING = {\n",
    "    'version': 1,\n",
    "    'disable_existing_loggers': True,  \n",
    "    'loggers': {\n",
    "        'ejemplo': {\n",
    "            'level': 'DEBUG',\n",
    "            'handlers': [\"console_handler\"]\n",
    "        },\n",
    "    }, \n",
    "    \"handlers\": {\n",
    "        'console_handler': {\n",
    "            'level': 'DEBUG',\n",
    "            'formatter': 'info',\n",
    "            'class': 'logging.StreamHandler',\n",
    "        },\n",
    "    },\n",
    "    \"formatters\": {\n",
    "        \"info\": {\n",
    "            'format': \"%(asctime)s [%(levelname)s]  %(message)s\"\n",
    "        },\n",
    "    }\n",
    "}\n",
    "\n",
    "logging.config.dictConfig(DEFAULT_LOGGING)"
   ]
  },
  {
   "cell_type": "code",
   "execution_count": 2,
   "metadata": {
    "slideshow": {
     "slide_type": "subslide"
    }
   },
   "outputs": [
    {
     "name": "stderr",
     "output_type": "stream",
     "text": [
      "2020-10-26 02:02:34,519 [DEBUG]  No logramos lograr ese logro\n"
     ]
    }
   ],
   "source": [
    "logger = logging.getLogger(\"ejemplo\")\n",
    "logger.debug(\"No logramos lograr ese logro\")"
   ]
  },
  {
   "cell_type": "markdown",
   "metadata": {
    "slideshow": {
     "slide_type": "subslide"
    }
   },
   "source": [
    "\n",
    "![](https://user-images.githubusercontent.com/2355719/91375459-26a98580-e7f1-11ea-9e67-53ea29fb4e5c.png)\n"
   ]
  },
  {
   "cell_type": "markdown",
   "metadata": {
    "slideshow": {
     "slide_type": "slide"
    }
   },
   "source": [
    "# ¿Pero no es muy complicado todo esto? \n",
    "\n",
    "![](https://i.imgflip.com/4ju828.jpg)\n"
   ]
  },
  {
   "cell_type": "markdown",
   "metadata": {
    "slideshow": {
     "slide_type": "subslide"
    }
   },
   "source": [
    "- La configuración no es trivial\n",
    "- Los *default* son malos\n",
    "- ¡Ni siquiera respeta PEP8!"
   ]
  },
  {
   "cell_type": "markdown",
   "metadata": {
    "slideshow": {
     "slide_type": "subslide"
    }
   },
   "source": [
    "<center>\n",
    "<img src=\"https://user-images.githubusercontent.com/2355719/91399775-f8d63800-e814-11ea-8cee-b56b888ebd8b.png\">\n",
    "    </center>\n",
    "\n",
    "`Structlog` es a `logging` lo que `requests` a `httplib`\n",
    "\n",
    "\n",
    "\n",
    "> It makes logging in Python less painful and more powerful by adding structure to your log entries.\n",
    ">\n",
    "> -- https://structlog.org"
   ]
  },
  {
   "cell_type": "code",
   "execution_count": 1,
   "metadata": {
    "slideshow": {
     "slide_type": "subslide"
    }
   },
   "outputs": [
    {
     "name": "stdout",
     "output_type": "stream",
     "text": [
      "\u001b[2m2020-10-26 11:19.00\u001b[0m \u001b[1mEl oceáno es muy grande y el submarino es muy pequeño\u001b[0m\n"
     ]
    }
   ],
   "source": [
    "import structlog\n",
    "\n",
    "# drop-in replacement! \n",
    "logger = structlog.get_logger()     \n",
    "logger.info(\"El oceáno es muy grande y el submarino es muy pequeño\")"
   ]
  },
  {
   "cell_type": "markdown",
   "metadata": {
    "slideshow": {
     "slide_type": "subslide"
    }
   },
   "source": [
    "### Lo importante: La mayoría de las veces necesitamos registrar **datos**\n",
    "\n",
    "(Ejemplos reales del código de mi trabajo, permiso)"
   ]
  },
  {
   "cell_type": "code",
   "execution_count": null,
   "metadata": {},
   "outputs": [],
   "source": [
    "logger.info(\n",
    "    \"Reserving inventory for (%s, %d, %d, %d, %d, %d)\",\n",
    "    sku,\n",
    "    warehouse_id,\n",
    "    account_id,\n",
    "    priority,\n",
    "    available_inventory,\n",
    "    required_quantity,\n",
    ")"
   ]
  },
  {
   "cell_type": "code",
   "execution_count": null,
   "metadata": {
    "slideshow": {
     "slide_type": "subslide"
    }
   },
   "outputs": [],
   "source": [
    "logger.warning(\n",
    "    \"LineItem points to an non-existent SKU\\n\"\n",
    "    \"LineItem (id, sku, account_id): (%d, %s, %s)\\n\"\n",
    "    \"Order (id, order_number): (%d, %s)\",\n",
    "    li.id,\n",
    "    li.sku,\n",
    "    li.account_id,\n",
    "    li.order.id,\n",
    "    li.order.order_number,\n",
    ")"
   ]
  },
  {
   "cell_type": "code",
   "execution_count": null,
   "metadata": {
    "slideshow": {
     "slide_type": "subslide"
    }
   },
   "outputs": [],
   "source": [
    "logger.info(\n",
    "    \"kit_allocations: %r\",\n",
    "    [\n",
    "        {\n",
    "            \"sku\": li.get(\"sku\"),\n",
    "            \"quantity\": li.get(\"quantity\"),\n",
    "            \"quantity_pending_fulfillment\": li.get(\"quantity_pending_fulfillment\"),\n",
    "            \"quantity_pending_allocation\": li.get(\"quantity_pending_allocation\"),\n",
    "        }\n",
    "        for li in kit_allocations\n",
    "    ],\n",
    ")"
   ]
  },
  {
   "cell_type": "markdown",
   "metadata": {
    "slideshow": {
     "slide_type": "subslide"
    }
   },
   "source": [
    "La manera de `structlog` es la manera `pythonica`: keyword arguments! "
   ]
  },
  {
   "cell_type": "code",
   "execution_count": 2,
   "metadata": {},
   "outputs": [
    {
     "name": "stdout",
     "output_type": "stream",
     "text": [
      "2020-10-26 11:19.09 Iniciamos conversaciones       interlocutor=FMI moneda=usd monto=52000000000.0 tipo_acuerdo=stand-by\n"
     ]
    }
   ],
   "source": [
    "logger.error(\"Iniciamos conversaciones\", interlocutor=\"FMI\", tipo_acuerdo=\"stand-by\", monto=52e9, moneda=\"usd\")"
   ]
  },
  {
   "cell_type": "markdown",
   "metadata": {
    "slideshow": {
     "slide_type": "subslide"
    }
   },
   "source": [
    "![](https://e00-elmundo.uecdn.es/assets/multimedia/imagenes/2018/03/28/15222363072573.jpg)"
   ]
  },
  {
   "cell_type": "code",
   "execution_count": null,
   "metadata": {},
   "outputs": [],
   "source": [
    "structlog.configure"
   ]
  },
  {
   "cell_type": "markdown",
   "metadata": {
    "slideshow": {
     "slide_type": "slide"
    }
   },
   "source": [
    "### Procesadores\n",
    "\n",
    "En `structlog` los `formatters` y `filters` se unifican en **processors**, \n"
   ]
  },
  {
   "cell_type": "code",
   "execution_count": 10,
   "metadata": {},
   "outputs": [
    {
     "name": "stdout",
     "output_type": "stream",
     "text": [
      "{\"tipo_conferencia\": \"grabada\", \"lira_turca\": 25.3, \"event\": \"todas las tormentas juntas\", \"level\": \"warning\", \"timestamp\": \"2020-10-26T04:10:34.829984Z\"}\n"
     ]
    }
   ],
   "source": [
    "structlog.configure(\n",
    "    processors=[\n",
    "        structlog.stdlib.add_log_level,\n",
    "        structlog.processors.TimeStamper(fmt=\"iso\"),\n",
    "        structlog.processors.JSONRenderer()\n",
    "    ]\n",
    ")\n",
    "\n",
    "logger = structlog.get_logger()\n",
    "logger.warning(\"todas las tormentas juntas\", tipo_conferencia=\"grabada\", lira_turca=25.3)"
   ]
  },
  {
   "cell_type": "markdown",
   "metadata": {
    "slideshow": {
     "slide_type": "subslide"
    }
   },
   "source": [
    "`JSONRenderer` usa `json.dumps` by default (configurable) pero es inteligente"
   ]
  },
  {
   "cell_type": "code",
   "execution_count": 13,
   "metadata": {},
   "outputs": [],
   "source": [
    "class Periodo:\n",
    "    def __repr__(self):\n",
    "        return \"50 años\"   \n",
    "\n",
    "p = Periodo()"
   ]
  },
  {
   "cell_type": "code",
   "execution_count": 14,
   "metadata": {},
   "outputs": [
    {
     "ename": "TypeError",
     "evalue": "Object of type Periodo is not JSON serializable",
     "output_type": "error",
     "traceback": [
      "\u001b[0;31m---------------------------------------------------------------------------\u001b[0m",
      "\u001b[0;31mTypeError\u001b[0m                                 Traceback (most recent call last)",
      "\u001b[0;32m<ipython-input-14-b4c9add0615f>\u001b[0m in \u001b[0;36m<module>\u001b[0;34m\u001b[0m\n\u001b[1;32m      1\u001b[0m \u001b[0;32mimport\u001b[0m \u001b[0mjson\u001b[0m\u001b[0;34m\u001b[0m\u001b[0;34m\u001b[0m\u001b[0m\n\u001b[0;32m----> 2\u001b[0;31m \u001b[0mjson\u001b[0m\u001b[0;34m.\u001b[0m\u001b[0mdumps\u001b[0m\u001b[0;34m(\u001b[0m\u001b[0mp\u001b[0m\u001b[0;34m)\u001b[0m\u001b[0;34m\u001b[0m\u001b[0;34m\u001b[0m\u001b[0m\n\u001b[0m",
      "\u001b[0;32m/usr/lib/python3.7/json/__init__.py\u001b[0m in \u001b[0;36mdumps\u001b[0;34m(obj, skipkeys, ensure_ascii, check_circular, allow_nan, cls, indent, separators, default, sort_keys, **kw)\u001b[0m\n\u001b[1;32m    229\u001b[0m         \u001b[0mcls\u001b[0m \u001b[0;32mis\u001b[0m \u001b[0;32mNone\u001b[0m \u001b[0;32mand\u001b[0m \u001b[0mindent\u001b[0m \u001b[0;32mis\u001b[0m \u001b[0;32mNone\u001b[0m \u001b[0;32mand\u001b[0m \u001b[0mseparators\u001b[0m \u001b[0;32mis\u001b[0m \u001b[0;32mNone\u001b[0m \u001b[0;32mand\u001b[0m\u001b[0;34m\u001b[0m\u001b[0;34m\u001b[0m\u001b[0m\n\u001b[1;32m    230\u001b[0m         default is None and not sort_keys and not kw):\n\u001b[0;32m--> 231\u001b[0;31m         \u001b[0;32mreturn\u001b[0m \u001b[0m_default_encoder\u001b[0m\u001b[0;34m.\u001b[0m\u001b[0mencode\u001b[0m\u001b[0;34m(\u001b[0m\u001b[0mobj\u001b[0m\u001b[0;34m)\u001b[0m\u001b[0;34m\u001b[0m\u001b[0;34m\u001b[0m\u001b[0m\n\u001b[0m\u001b[1;32m    232\u001b[0m     \u001b[0;32mif\u001b[0m \u001b[0mcls\u001b[0m \u001b[0;32mis\u001b[0m \u001b[0;32mNone\u001b[0m\u001b[0;34m:\u001b[0m\u001b[0;34m\u001b[0m\u001b[0;34m\u001b[0m\u001b[0m\n\u001b[1;32m    233\u001b[0m         \u001b[0mcls\u001b[0m \u001b[0;34m=\u001b[0m \u001b[0mJSONEncoder\u001b[0m\u001b[0;34m\u001b[0m\u001b[0;34m\u001b[0m\u001b[0m\n",
      "\u001b[0;32m/usr/lib/python3.7/json/encoder.py\u001b[0m in \u001b[0;36mencode\u001b[0;34m(self, o)\u001b[0m\n\u001b[1;32m    197\u001b[0m         \u001b[0;31m# exceptions aren't as detailed.  The list call should be roughly\u001b[0m\u001b[0;34m\u001b[0m\u001b[0;34m\u001b[0m\u001b[0;34m\u001b[0m\u001b[0m\n\u001b[1;32m    198\u001b[0m         \u001b[0;31m# equivalent to the PySequence_Fast that ''.join() would do.\u001b[0m\u001b[0;34m\u001b[0m\u001b[0;34m\u001b[0m\u001b[0;34m\u001b[0m\u001b[0m\n\u001b[0;32m--> 199\u001b[0;31m         \u001b[0mchunks\u001b[0m \u001b[0;34m=\u001b[0m \u001b[0mself\u001b[0m\u001b[0;34m.\u001b[0m\u001b[0miterencode\u001b[0m\u001b[0;34m(\u001b[0m\u001b[0mo\u001b[0m\u001b[0;34m,\u001b[0m \u001b[0m_one_shot\u001b[0m\u001b[0;34m=\u001b[0m\u001b[0;32mTrue\u001b[0m\u001b[0;34m)\u001b[0m\u001b[0;34m\u001b[0m\u001b[0;34m\u001b[0m\u001b[0m\n\u001b[0m\u001b[1;32m    200\u001b[0m         \u001b[0;32mif\u001b[0m \u001b[0;32mnot\u001b[0m \u001b[0misinstance\u001b[0m\u001b[0;34m(\u001b[0m\u001b[0mchunks\u001b[0m\u001b[0;34m,\u001b[0m \u001b[0;34m(\u001b[0m\u001b[0mlist\u001b[0m\u001b[0;34m,\u001b[0m \u001b[0mtuple\u001b[0m\u001b[0;34m)\u001b[0m\u001b[0;34m)\u001b[0m\u001b[0;34m:\u001b[0m\u001b[0;34m\u001b[0m\u001b[0;34m\u001b[0m\u001b[0m\n\u001b[1;32m    201\u001b[0m             \u001b[0mchunks\u001b[0m \u001b[0;34m=\u001b[0m \u001b[0mlist\u001b[0m\u001b[0;34m(\u001b[0m\u001b[0mchunks\u001b[0m\u001b[0;34m)\u001b[0m\u001b[0;34m\u001b[0m\u001b[0;34m\u001b[0m\u001b[0m\n",
      "\u001b[0;32m/usr/lib/python3.7/json/encoder.py\u001b[0m in \u001b[0;36miterencode\u001b[0;34m(self, o, _one_shot)\u001b[0m\n\u001b[1;32m    255\u001b[0m                 \u001b[0mself\u001b[0m\u001b[0;34m.\u001b[0m\u001b[0mkey_separator\u001b[0m\u001b[0;34m,\u001b[0m \u001b[0mself\u001b[0m\u001b[0;34m.\u001b[0m\u001b[0mitem_separator\u001b[0m\u001b[0;34m,\u001b[0m \u001b[0mself\u001b[0m\u001b[0;34m.\u001b[0m\u001b[0msort_keys\u001b[0m\u001b[0;34m,\u001b[0m\u001b[0;34m\u001b[0m\u001b[0;34m\u001b[0m\u001b[0m\n\u001b[1;32m    256\u001b[0m                 self.skipkeys, _one_shot)\n\u001b[0;32m--> 257\u001b[0;31m         \u001b[0;32mreturn\u001b[0m \u001b[0m_iterencode\u001b[0m\u001b[0;34m(\u001b[0m\u001b[0mo\u001b[0m\u001b[0;34m,\u001b[0m \u001b[0;36m0\u001b[0m\u001b[0;34m)\u001b[0m\u001b[0;34m\u001b[0m\u001b[0;34m\u001b[0m\u001b[0m\n\u001b[0m\u001b[1;32m    258\u001b[0m \u001b[0;34m\u001b[0m\u001b[0m\n\u001b[1;32m    259\u001b[0m def _make_iterencode(markers, _default, _encoder, _indent, _floatstr,\n",
      "\u001b[0;32m/usr/lib/python3.7/json/encoder.py\u001b[0m in \u001b[0;36mdefault\u001b[0;34m(self, o)\u001b[0m\n\u001b[1;32m    177\u001b[0m \u001b[0;34m\u001b[0m\u001b[0m\n\u001b[1;32m    178\u001b[0m         \"\"\"\n\u001b[0;32m--> 179\u001b[0;31m         raise TypeError(f'Object of type {o.__class__.__name__} '\n\u001b[0m\u001b[1;32m    180\u001b[0m                         f'is not JSON serializable')\n\u001b[1;32m    181\u001b[0m \u001b[0;34m\u001b[0m\u001b[0m\n",
      "\u001b[0;31mTypeError\u001b[0m: Object of type Periodo is not JSON serializable"
     ]
    }
   ],
   "source": [
    "import json \n",
    "json.dumps(p)  "
   ]
  },
  {
   "cell_type": "code",
   "execution_count": 15,
   "metadata": {
    "slideshow": {
     "slide_type": "subslide"
    }
   },
   "outputs": [
    {
     "name": "stdout",
     "output_type": "stream",
     "text": [
      "{\"periodo\": \"50 a\\u00f1os\", \"event\": \"el mejor equipo\", \"level\": \"info\", \"timestamp\": \"2020-10-26T04:20:58.496938Z\"}\n"
     ]
    }
   ],
   "source": [
    "logger.info(\"el mejor equipo\", periodo=p)"
   ]
  },
  {
   "cell_type": "code",
   "execution_count": 16,
   "metadata": {},
   "outputs": [
    {
     "name": "stdout",
     "output_type": "stream",
     "text": [
      "{\"hasta\": \"hasta el 11 de agosto\", \"event\": \"gobierno economico\", \"level\": \"info\", \"timestamp\": \"2020-10-26T04:22:28.040188Z\"}\n"
     ]
    }
   ],
   "source": [
    "class PeriodoReal(C):\n",
    "    def __structlog__(self):\n",
    "        return \"hasta el 11 de agosto\"\n",
    "\n",
    "logger.info(\"gobierno economico\", hasta=PeriodoReal())"
   ]
  },
  {
   "cell_type": "markdown",
   "metadata": {},
   "source": [
    "## Formatos de salida"
   ]
  },
  {
   "cell_type": "markdown",
   "metadata": {},
   "source": [
    "`structlog` tiene procesadores \"amigables\" con el desarrollo"
   ]
  },
  {
   "cell_type": "code",
   "execution_count": 3,
   "metadata": {
    "slideshow": {
     "slide_type": "slide"
    }
   },
   "outputs": [
    {
     "name": "stdout",
     "output_type": "stream",
     "text": [
      "\u001b[2m2020-10-26 14:40.10\u001b[0m [\u001b[32m\u001b[1minfo     \u001b[0m] \u001b[1mes todo mentira               \u001b[0m \u001b[36mtema\u001b[0m=\u001b[35mautopistas\u001b[0m\n"
     ]
    }
   ],
   "source": [
    "import structlog\n",
    "\n",
    "structlog.configure( \n",
    "        processors=[ \n",
    "            structlog.stdlib.add_log_level, \n",
    "            structlog.processors.TimeStamper(fmt=\"%Y-%m-%d %H:%M.%S\"), \n",
    "            structlog.dev.ConsoleRenderer() \n",
    "        ]\n",
    ") \n",
    "logger = structlog.get_logger() \n",
    "\n",
    "logger.info(\"es todo mentira\", tema=\"autopistas\")"
   ]
  },
  {
   "cell_type": "markdown",
   "metadata": {
    "slideshow": {
     "slide_type": "subslide"
    }
   },
   "source": [
    "## En producción: json\n",
    "\n",
    "- JSON un formato amigable con humanos, y universal para compartir datos. \n",
    "- No hace falta regex ni nada para parsear, vienen con estructura y tipo de datos básicos! \n",
    "- Muchos sistemas habilitan busqueda avanzada\n",
    "\n",
    "**Ejemplo de Cloudwatch\n",
    "\n",
    "![](https://user-images.githubusercontent.com/2355719/91386364-3b921300-e809-11ea-9629-70582e05c13e.png)\n",
    "\n"
   ]
  },
  {
   "cell_type": "markdown",
   "metadata": {
    "slideshow": {
     "slide_type": "slide"
    }
   },
   "source": [
    "## Contextos\n",
    "\n"
   ]
  },
  {
   "cell_type": "code",
   "execution_count": 1,
   "metadata": {
    "slideshow": {
     "slide_type": "subslide"
    }
   },
   "outputs": [
    {
     "name": "stdout",
     "output_type": "stream",
     "text": [
      "Overwriting a_module.py\n"
     ]
    }
   ],
   "source": [
    "%%writefile a_module.py\n",
    "\n",
    "from structlog import get_logger\n",
    "\n",
    "logger = get_logger()\n",
    "\n",
    "def some_function():\n",
    "    logger.error(\"escuchas\", tipo=\"ilegales\", respuesta=\"cuentapropistas\") "
   ]
  },
  {
   "cell_type": "code",
   "execution_count": 8,
   "metadata": {
    "slideshow": {
     "slide_type": "subslide"
    }
   },
   "outputs": [],
   "source": [
    "import sys\n",
    "import logging\n",
    "import structlog\n",
    "from a_module import some_function\n",
    "\n",
    "logging.basicConfig(\n",
    "    format=\"%(message)s\", stream=sys.stdout, level=logging.INFO\n",
    ")\n",
    "structlog.configure(\n",
    "    processors=[\n",
    "        structlog.processors.TimeStamper(fmt=\"iso\"),\n",
    "        structlog.processors.KeyValueRenderer(\n",
    "            key_order=[\"timestamp\", \"event\"]\n",
    "        ),\n",
    "    ],\n",
    "    context_class=structlog.threadlocal.wrap_dict(dict),\n",
    "    logger_factory=structlog.stdlib.LoggerFactory(),\n",
    ")\n"
   ]
  },
  {
   "cell_type": "code",
   "execution_count": 9,
   "metadata": {},
   "outputs": [
    {
     "name": "stdout",
     "output_type": "stream",
     "text": [
      "timestamp='2020-10-26T04:58:01.123994Z' event='inicio entrevista' periodista='amigo'\n",
      "timestamp='2020-10-26T04:58:01.125263Z' event='escuchas' periodista='amigo' sobre=4 tipo='ilegales' respuesta='cuentapropistas'\n",
      "timestamp='2020-10-26T04:58:01.126142Z' event='final entrevista' sobre=4\n"
     ]
    }
   ],
   "source": [
    "def entrevista():\n",
    "    log = logger.new(periodista=\"amigo\")     # set a new context. any futher event from the logger will get x for free\n",
    "    log.warning(\"inicio entrevista\")\n",
    "    log = log.bind(sobre=4)   # update the context\n",
    "    some_function()                 \n",
    "    \n",
    "    log = log.unbind(\"periodista\")\n",
    "    log.warning(\"final entrevista\")\n",
    "    \n",
    "entrevista()"
   ]
  },
  {
   "cell_type": "markdown",
   "metadata": {
    "slideshow": {
     "slide_type": "slide"
    }
   },
   "source": [
    "## Consejos / Buenas Prácticas \n"
   ]
  },
  {
   "cell_type": "markdown",
   "metadata": {
    "slideshow": {
     "slide_type": "subslide"
    }
   },
   "source": [
    "- A veces loggeamos mucho pero no siempre efectivamente. \n",
    "\n",
    "  - Loggear transiciones de estado\n",
    "  - Mientras más \"raro\" el evento, mayor nivel y detalle \n",
    "  - ¡Quitar ruido!  "
   ]
  },
  {
   "cell_type": "markdown",
   "metadata": {
    "slideshow": {
     "slide_type": "subslide"
    }
   },
   "source": [
    "- Es barato pero no gratis. \n",
    "\n",
    "   - Usar bien los niveles y filtros.  \n",
    "   - No duplicar handlers \n",
    "   - Delegar todo lo que se pueda a la \"infra\" (storage, rotación de archivos)"
   ]
  },
  {
   "cell_type": "markdown",
   "metadata": {
    "slideshow": {
     "slide_type": "subslide"
    }
   },
   "source": [
    "- Además de timestamp, agregar info de trazabilidad: request_id, thread_id, user_id, etc.\n",
    "\n",
    " - Timestamps en UTC\n",
    " - Tokens de trazabilidad únicos"
   ]
  },
  {
   "cell_type": "markdown",
   "metadata": {
    "slideshow": {
     "slide_type": "subslide"
    }
   },
   "source": [
    "- Structlog es fácil, poderoso y pythónico: úsenlo! \n",
    "   \n",
    "   - también miren Loguru"
   ]
  },
  {
   "cell_type": "markdown",
   "metadata": {
    "slideshow": {
     "slide_type": "subslide"
    }
   },
   "source": [
    "- Configuración\n",
    "\n",
    "   - Tan tarde como se pueda, antes de que comience a ejecutarse **tu código**\n",
    "   - Procurá que se haga una única vez\n",
    "   - Adaptarse a convenciones del framework (si existen)\n",
    "   - Podés reconfigurar loggers de terceros\n",
    "   - Structlog justo despues de logging estándar,  via `stdlib.LoggerFactory`"
   ]
  },
  {
   "cell_type": "markdown",
   "metadata": {
    "slideshow": {
     "slide_type": "subslide"
    }
   },
   "source": [
    "- Usen barbijo y cuídense\n"
   ]
  },
  {
   "cell_type": "markdown",
   "metadata": {
    "slideshow": {
     "slide_type": "slide"
    }
   },
   "source": [
    "### Caricias significativas con el codo\n",
    "\n",
    "![image](https://user-images.githubusercontent.com/2355719/97137378-70044b80-1734-11eb-90d8-4209b204fc1d.png)\n"
   ]
  }
 ],
 "metadata": {
  "celltoolbar": "Slideshow",
  "kernelspec": {
   "display_name": "Python 3",
   "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.7.4"
  }
 },
 "nbformat": 4,
 "nbformat_minor": 4
}