notebooks/05-operations/02-logs-asynch.ipynb

{
 "cells": [
  {
   "cell_type": "markdown",
   "id": "c9fc0614-4eec-4c39-ad22-ea10afa00e9d",
   "metadata": {},
   "source": [
    "# Streaming and SQL-based ingestion logs\n",
    "\n",
    "Apache Druid uses Log4J to emit information as it runs. They not only enable you to investigate issues and solve problems, but to understand how each of Druid's processes work in isolation and in collaboration with one another.\n",
    "\n",
    "As well as the usual processes in Druid, Druid's highly-parallelised approach to both [streaming](https://druid.apache.org/docs/latest/ingestion/#streaming) and [batch](https://druid.apache.org/docs/latest/ingestion/#batch) ingestion is carried out by worker tasks. Each of these is a separate process that create their own log files.\n",
    "\n",
    "In this notebook, you will look at log files for the key processes in SQL-based ingestion as well as the spawned peon processes, and see where to look to point the all-important task log files to durable storage."
   ]
  },
  {
   "cell_type": "markdown",
   "id": "e8dbaa49-8368-45cd-82da-2e358d17fdc4",
   "metadata": {},
   "source": [
    "## Prerequisites\n",
    "\n",
    "This tutorial works with Druid 30.0.0 or later. It is designed to run from a Mac with a locally running instance of Druid but can also be run on common Linux distributions and on Windows with [WSL (Windows Subsystem for Linux)](https://learn.microsoft.com/en-us/windows/wsl/).\n",
    "\n",
    "If you wish to use this tutorial within Jupyter through the [learn-druid](https://github.com/implydata/learn-druid) Docker Compose, use the `jupyter` profile to avoid starting a second instance of Druid that may cause conflicts."
   ]
  },
  {
   "cell_type": "markdown",
   "id": "151ede96-348f-423c-adc7-0e23c6910b9e",
   "metadata": {},
   "source": [
    "## Initialization\n",
    "\n",
    "In this step, you will find instructions to install prerequisite tools and to deploy Druid locally.\n",
    "\n",
    "Before starting, open a terminal window.\n",
    "\n",
    "### Install required tools\n",
    "\n",
    "You will need the following tools:\n",
    "\n",
    "* `brew` to install prerequisite tools.\n",
    "* `wget` to pull Apache Druid from the official repository.\n",
    "* `multitail` to view multiple logs files simultaneously.\n",
    "\n",
    "For instructions on installing `brew`, see the [Homebrew homepage](https://brew.sh/).\n",
    "\n",
    "Install `wget` and `multitail` using `brew`. For example:\n",
    "\n",
    "```bash\n",
    "brew install multitail\n",
    "brew install wget\n",
    "```\n",
    "\n",
    "You may need to manually fetch a default configuration for `multitail`.\n",
    "\n",
    "Skip this step if you are already running `multitail` as it will overwrite your own configuration.\n",
    "\n",
    "Execute the following command to pull the default configuration to your home folder.\n",
    "\n",
    "```bash\n",
    "curl https://raw.githubusercontent.com/halturin/multitail/master/multitail.conf > ~/.multitailrc\n",
    "```\n",
    "\n",
    "### Install Apache Druid\n",
    "\n",
    "Run the following to create a dedicated folder for learn-druid in your home directory:\n",
    "\n",
    "```bash\n",
    "cd ~ ; mkdir learn-druid-local\n",
    "cd learn-druid-local\n",
    "```\n",
    "\n",
    "Pull and unpack a compatible version of Apache Druid from the [Apache Druid downloads page](https://dlcdn.apache.org/druid/), for example `30.0.0`.\n",
    "\n",
    "```bash\n",
    "version=\"30.0.0\"\n",
    "wget https://dlcdn.apache.org/druid/$version/apache-druid-$version-bin.tar.gz\n",
    "tar -xzf apache-druid-$version-bin.tar.gz\n",
    "```\n",
    "\n",
    "Use the following commands to rename the folder.\n",
    "\n",
    "```bash\n",
    "mv apache-druid-$version apache-druid\n",
    "cd apache-druid\n",
    "```"
   ]
  },
  {
   "cell_type": "markdown",
   "id": "65384957-3c3f-43fb-b296-7e5f7fddbcc5",
   "metadata": {},
   "source": [
    "## Process logs\n",
    "\n",
    "Understand [SQL-based ingestion](https://druid.apache.org/docs/latest/multi-stage-query/concepts.html) planning and execution by monitoring logs emitted from the [core processes for ingestion](https://druid.apache.org/docs/latest/ingestion/):\n",
    "\n",
    "* Router\n",
    "* Overlord\n",
    "* MiddleManager\n",
    "* Historical\n",
    "\n",
    "Start Druid as a background task with the following command:\n",
    "\n",
    "```bash\n",
    "nohup ~/learn-druid-local/apache-druid/bin/start-druid & disown > log.out 2> log.err < /dev/null\n",
    "```\n",
    "\n",
    "In the terminal window, switch to the default log location:\n",
    "\n",
    "```bash\n",
    "cd log\n",
    "```\n",
    "\n",
    "Run the following command to start monitoring these logs.\n",
    "\n",
    "```bash\n",
    "multitail -CS log4jnew -du -P a -s 2 -sn 1,2 \\\n",
    "    -f coordinator-overlord.log \\\n",
    "    -f middleManager.log \\\n",
    "    -f historical.log\n",
    "```"
   ]
  },
  {
   "cell_type": "markdown",
   "id": "34a76a25-e488-4f2c-98cc-e17e6df81f73",
   "metadata": {},
   "source": [
    "In the multitail window, press `0`, `1`, and `2` in turn to add a line marker to the log output.\n",
    "\n",
    "Open a second terminal window, and run the following command to start an ingestion:\n",
    "\n",
    "```bash\n",
    "curl --location --request POST 'http://localhost:8888/druid/v2/sql/task/' \\\n",
    "  --header 'Content-Type: application/json' \\\n",
    "  --data-raw '{\n",
    "    \"query\": \"INSERT INTO \\\"example-wikipedia-logs\\\"\\nSELECT\\n  TIME_PARSE(\\\"timestamp\\\") AS __time,\\n  *\\nFROM TABLE(\\n  EXTERN(\\n    '\\''{\\\"type\\\": \\\"http\\\", \\\"uris\\\": [\\\"https://druid.apache.org/data/wikipedia.json.gz\\\"]}'\\'',\\n    '\\''{\\\"type\\\": \\\"json\\\"}'\\'',\\n    '\\''[{\\\"name\\\": \\\"added\\\", \\\"type\\\": \\\"long\\\"}, {\\\"name\\\": \\\"channel\\\", \\\"type\\\": \\\"string\\\"}, {\\\"name\\\": \\\"cityName\\\", \\\"type\\\": \\\"string\\\"}, {\\\"name\\\": \\\"comment\\\", \\\"type\\\": \\\"string\\\"}, {\\\"name\\\": \\\"commentLength\\\", \\\"type\\\": \\\"long\\\"}, {\\\"name\\\": \\\"countryIsoCode\\\", \\\"type\\\": \\\"string\\\"}, {\\\"name\\\": \\\"countryName\\\", \\\"type\\\": \\\"string\\\"}, {\\\"name\\\": \\\"deleted\\\", \\\"type\\\": \\\"long\\\"}, {\\\"name\\\": \\\"delta\\\", \\\"type\\\": \\\"long\\\"}, {\\\"name\\\": \\\"deltaBucket\\\", \\\"type\\\": \\\"string\\\"}, {\\\"name\\\": \\\"diffUrl\\\", \\\"type\\\": \\\"string\\\"}, {\\\"name\\\": \\\"flags\\\", \\\"type\\\": \\\"string\\\"}, {\\\"name\\\": \\\"isAnonymous\\\", \\\"type\\\": \\\"string\\\"}, {\\\"name\\\": \\\"isMinor\\\", \\\"type\\\": \\\"string\\\"}, {\\\"name\\\": \\\"isNew\\\", \\\"type\\\": \\\"string\\\"}, {\\\"name\\\": \\\"isRobot\\\", \\\"type\\\": \\\"string\\\"}, {\\\"name\\\": \\\"isUnpatrolled\\\", \\\"type\\\": \\\"string\\\"}, {\\\"name\\\": \\\"metroCode\\\", \\\"type\\\": \\\"string\\\"}, {\\\"name\\\": \\\"namespace\\\", \\\"type\\\": \\\"string\\\"}, {\\\"name\\\": \\\"page\\\", \\\"type\\\": \\\"string\\\"}, {\\\"name\\\": \\\"regionIsoCode\\\", \\\"type\\\": \\\"string\\\"}, {\\\"name\\\": \\\"regionName\\\", \\\"type\\\": \\\"string\\\"}, {\\\"name\\\": \\\"timestamp\\\", \\\"type\\\": \\\"string\\\"}, {\\\"name\\\": \\\"user\\\", \\\"type\\\": \\\"string\\\"}]'\\''\\n  )\\n)\\nPARTITIONED BY DAY\"\n",
    "  }'\n",
    "```\n",
    "\n",
    "Open Coordinator and Overlog combined log in a separate panel by pressing `b` and select the `coordinator-overlord` option.\n",
    "\n",
    "Repeat pressing `b` until you find your line marker and notice the execution history is logged in detail:\n",
    "\n",
    "* Tasks are queued up (`org.apache.druid.indexing.overlord.hrtr.HttpRemoteTaskRunner`).\n",
    "* Detail is written to the Metadata Database (`org.apache.druid.indexing.overlord.MetadataTaskStorage`).\n",
    "* Segments identifiers are allocated and then created (`org.apache.druid.indexing.overlord.TaskLockbox`).\n",
    "* Segments are completed and the shutdown is recognised.\n",
    "* Segments are published to the metadata database (`Published segments to DB...`).\n",
    "\n",
    "Press `q` to exit the panel, and then hit `b` and open the Middle Manager logs.\n",
    "\n",
    "> Use `Y` in the `multitail` window to switch line wrapping on and off.\n",
    "\n",
    "In the `middleManager` log, notice:\n",
    "\n",
    "* The creation of Task Runners, each with their own Java configurations (`org.apache.druid.indexing.overlord.ForkingTaskRunner`).\n",
    "* `FileTaskLogs` writing logs to specific folders for each Task Runner.\n",
    "* Tasks being recorded as completed (`Task [---] completed with status [SUCCESS]`).\n",
    "\n",
    "Press `q` to exit the panel, then hit `b` and open the Historical log.\n",
    "\n",
    "Notice how the Historical process sees the segments and loads these from Deep Storage (being in `var/druid/segments` in this environment) and into its own local Segment Metadata cache (being in `var/druid/segment-cache`).\n",
    "\n",
    "Spend some time looking through this log. Can you find the following important information about Druid's ingestion service?\n",
    "\n",
    "* Ingestion planning at the Overlord.\n",
    "* Parallel ingestion task creation and execution from the Overlord to the Middle Manager.\n",
    "* Segment publishing by the Overlord after task completion.\n",
    "* Data distribution by the Coordinator and Historicals.\n",
    "\n",
    "When you are finished, type `q` to quit `multitail`."
   ]
  },
  {
   "cell_type": "markdown",
   "id": "b680cce2-652c-447c-b96e-6be0bc61ab54",
   "metadata": {},
   "source": [
    "## Task logs\n",
    "\n",
    "In the example above, the MiddleManager spawned multiple other tasks (peons) that created logs then [written to a log location](https://druid.apache.org/docs/latest/ingestion/tasks#task-logs) that you can configure as an administrator.\n",
    "\n",
    "Run this command to view the `common.runtime.properties` for the `start-druid` environment.\n",
    "\n",
    "```bash\n",
    "cat ~/learn-druid-local/apache-druid/conf/druid/auto/_common/common.runtime.properties\n",
    "```"
   ]
  },
  {
   "cell_type": "markdown",
   "id": "28c0f9d0-9127-4d2c-a97e-d205fafae862",
   "metadata": {},
   "source": [
    "### Viewing local logs\n",
    "\n",
    "The \"Indexing Service Logs\" section contains the configuration that caused the Middle Manager to write its logs to local disk:\n",
    "\n",
    "```\n",
    "druid.indexer.logs.type=file\n",
    "druid.indexer.logs.directory=var/druid/indexing-logs\n",
    "```\n",
    "\n",
    "Run this command to see where task logs were written by looking at the Middle Manager log:\n",
    "\n",
    "```bash\n",
    "grep \"Wrote task log to\" middleManager.log\n",
    "```\n",
    "\n",
    "Notice that the log filename is made up of the query ID and the suffix `.log`.\n",
    "\n",
    "Adapt the following `vi` command to open the log for viewing:\n",
    "\n",
    "```bash\n",
    "vi ~/learn-druid-local/apache-druid/<logfilelocation>\n",
    "```\n",
    "\n",
    "For example,\n",
    "\n",
    "```bash\n",
    "vi ~/learn-druid-local/apache-druid/var/druid/indexing-logsquery-83651faf-d179-4f4d-b0ad-ce61e36e85bd-worker0_0.log\n",
    "```\n",
    "\n",
    "The logs contain a large amount of information helpful in understanding what Druid does during an ingestion. \n",
    "\n",
    "* The initial Java process spin-up.\n",
    "* Records of activity, broken up into \"lifecycle stages\" (`org.apache.druid.java.util.common.lifecycle.Lifecycle')\n",
    "* The actual creation of segment files and their publication.\n",
    "* A JSON object containing the task completion status.\n",
    "\n",
    "Type `:q` and press enter to quit `vi`."
   ]
  },
  {
   "cell_type": "markdown",
   "id": "2e7474ae-cff4-47e4-b7ce-b80b786e3892",
   "metadata": {},
   "source": [
    "### Viewing logs via the API\n",
    "\n",
    "Use the task log API with a query ID to access the logs over HTTP. This is the same as is used on the console to view logs.\n",
    "\n",
    "When calling the API, you can use the Ids in the log files, or call the Tasks API to list all possible task IDs:\n",
    "\n",
    "```bash\n",
    "curl -s http://localhost:8081/druid/indexer/v1/tasks | jq '.[].id'\n",
    "```\n",
    "\n",
    "Switch `<queryID>` for an ID and then run it to pull the log file of one of the tasks.\n",
    "\n",
    "```bash\n",
    "curl http://localhost:8888/druid/indexer/v1/task/<queryID>/log\n",
    "```\n",
    "\n",
    "For example:\n",
    "\n",
    "```bash\n",
    "curl http://localhost:8888/druid/indexer/v1/task/query-83651faf-d179-4f4d-b0ad-ce61e36e85bd-worker0_0/log\n",
    "```\n",
    "\n",
    "Repeat the API call removing the `-worker0_0` portion. This will retrieve the overall log for the ingestion."
   ]
  },
  {
   "cell_type": "markdown",
   "id": "6d37572a-6c69-42a0-9ac2-377f3e66e456",
   "metadata": {},
   "source": [
    "### Configuring long-term log storage\n",
    "\n",
    "In a typical cluster with multiple nodes and Middle Managers, [configure a centralized log location](https://druid.apache.org/docs/latest/configuration/#task-logging). Processes will then migrate local log files to the long-term storage area, which is an important implementation step in a production environment.\n",
    "\n",
    "Then either use a viewing tool for your configured long-term storage, or the API and / or console to view logs."
   ]
  },
  {
   "cell_type": "markdown",
   "id": "b0d02e81-4bb2-4469-b534-19e970f8c828",
   "metadata": {},
   "source": [
    "## Task log retention\n",
    "\n",
    "Use `druid.indexer.logs.kill` settings in your Overlord `runtime.properties` to have Druid [manage the retention of task log files](https://druid.apache.org/docs/latest/configuration/#log-retention-policy) centrally as part of [on-going cluster hygiene](https://druid.apache.org/docs/latest/operations/clean-metadata-store#indexer-task-logs).\n",
    "\n",
    "Run the following to take a copy of your existing runtime configuration for the Coordinator and Overlord:\n",
    "\n",
    "```\n",
    "cp ~/learn-druid-local/apache-druid/conf/druid/auto/coordinator-overlord/runtime.properties ~/learn-druid-local/apache-druid/conf/druid/auto/coordinator-overlord/runtime.properties.old\n",
    "```\n",
    "\n",
    "Before you change the configuration, stop your Druid instance by running this command:\n",
    "\n",
    "```bash\n",
    "kill $(ps -ef | grep 'supervise' | awk 'NF{print $2}' | head -n 1)\n",
    "```\n",
    "\n",
    "Now run the following to add a retention configuration that will delete task logs after 30 seconds:\n",
    "\n",
    "```bash\n",
    "echo -e \"druid.indexer.logs.kill.enabled=true\\ndruid.indexer.logs.kill.durationToRetain=30000\\ndruid.indexer.logs.kill.initialDelay=100\\ndruid.indexer.logs.kill.delay=100\" >> ~/learn-druid-local/apache-druid/conf/druid/auto/coordinator-overlord/runtime.properties\n",
    "```\n",
    "\n",
    "* `druid.indexer.logs.kill.enabled` to true tells Druid to delete old task log files.\n",
    "* `druid.indexer.logs.kill.durationToRetain` tells Druid how old (in milliseconds) log files must be to be deleted.\n",
    "* `druid.indexer.logs.kill.initialDelay` tells Druid how long to wait (in milliseconds) before attempting to delete old log files.\n",
    "* `druid.indexer.logs.kill.delay` tells Druid how long to wait (in milliseconds) after between attempting to delete old log files for the first time since the process started.\n",
    "\n",
    "View the resulting configuration with a `cat`:\n",
    "\n",
    "```bash\n",
    "cat ~/learn-druid-local/apache-druid/conf/druid/auto/coordinator-overlord/runtime.properties\n",
    "```\n",
    "\n",
    "Run the following command to switch to the Indexing Logs location:\n",
    "\n",
    "```bash\n",
    "cd ~/learn-druid-local/apache-druid/var/druid/indexing-logs ; ls -l\n",
    "```\n",
    "\n",
    "Now restart Druid:\n",
    "\n",
    "```bash\n",
    "nohup ~/learn-druid-local/apache-druid/bin/start-druid ; disown > log.out 2> log.err < /dev/null ; disown\n",
    "```\n",
    "\n",
    "Running this command will show that the older task logs have now been deleted:\n",
    "\n",
    "```bash\n",
    "ls -l\n",
    "```"
   ]
  },
  {
   "cell_type": "markdown",
   "id": "1023e5a3-cedc-435f-a448-30f8c3ae1535",
   "metadata": {},
   "source": [
    "# Stop Druid\n",
    "\n",
    "Return the configuration to stop Druid.\n",
    "\n",
    "```bash\n",
    "kill $(ps -ef | grep 'supervise' | awk 'NF{print $2}' | head -n 1)\n",
    "```\n",
    "\n",
    "Run this final cell to restore the default configuration for your runtime properties files:\n",
    "\n",
    "```bash\n",
    "rm ~/learn-druid-local/apache-druid/conf/druid/auto/coordinator-overlord/runtime.properties ; \\\n",
    "mv ~/learn-druid-local/apache-druid/conf/druid/auto/coordinator-overlord/runtime.properties.old ~/learn-druid-local/apache-druid/conf/druid/auto/coordinator-overlord/runtime.properties\n",
    "``` "
   ]
  },
  {
   "cell_type": "markdown",
   "id": "57d5921b-636e-4a85-ae4d-dc0239bfef0b",
   "metadata": {},
   "source": [
    "## Learn more\n",
    "\n",
    "In this notebook you've seen how you can use Linux tools to inspect the logs of processes involved in ingestion, and seen the kinds of information that they contain. You've also seen the task-specific log files and read about how to configure Druid for long-term retention.\n",
    "\n",
    "* Read more about [Process logs](https://druid.apache.org/docs/latest/configuration/logging.html) and [Task logs](https://druid.apache.org/docs/latest/ingestion/tasks.html#task-logs) in the official documentation, as well as:\n",
    "  * [Task log configuration for remote storage](https://druid.apache.org/docs/latest/configuration/index.html#task-logging) and\n",
    "  * [Task log configuration for retention](https://druid.apache.org/docs/latest/configuration/#log-retention-policy)."
   ]
  }
 ],
 "metadata": {
  "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.11.6"
  }
 },
 "nbformat": 4,
 "nbformat_minor": 5
}