{"id":2988,"date":"2025-01-07T19:49:51","date_gmt":"2025-01-08T01:49:51","guid":{"rendered":"https:\/\/readme.com\/resources\/?p=2988"},"modified":"2025-12-15T17:06:33","modified_gmt":"2025-12-15T23:06:33","slug":"making-better-use-of-herokus-logging-firehose","status":"publish","type":"post","link":"https:\/\/readme.com\/resources\/making-better-use-of-herokus-logging-firehose","title":{"rendered":"Making Better Use of Heroku\u2019s Logging Firehose"},"content":{"rendered":"\n

This past month at ReadMe has been quite productive! We hosted a 24 hour API radio station<\/a>, deployed a huge v6 of our API explorer<\/a>, reimagined our Markdown engine<\/a>, and released an app on Glitch<\/a> showcasing how we\u2019re able to demo Developer Metrics<\/a>.<\/p>\n\n\n\n

What better time is there than now to tackle a longstanding project that completely rearchitects how we store, and use, HTTP logs?<\/p>\n\n\n\n

70 psi<\/h3>\n\n\n\n

Historically at ReadMe, our usage of HTTP logs has been extremely lackluster. We either didn\u2019t store valuable information, stored too much unnecessary data that made finding issues difficult, if not impossible, or the logging platform we used made navigating logs a chore.<\/p>\n\n\n\n

ReadMe runs on Heroku, so the logs that we have access to via heroku logs --tail<\/code> are a raw firehose of data from their Logplex router<\/a>. Have you ever turned a hose on a dog and watched them try, and fail, in spectacular fashion, to gobble up all of the water? That was us trying to make use of this supersonic stream of logs.<\/p>\n\n\n\n

ELK<\/h3>\n\n\n\n

I fell in love with Kibana<\/a> when I was working at Vimeo on its API. The dashboards we were able to construct allowed us to quickly, and easily, find and discover problems in the platform before they became problems. This is something I\u2019ve been evangelizing since coming to ReadMe.<\/p>\n\n\n\n

The problem, however, is that there isn\u2019t a one-click Heroku marketplace solution for extracting logs into an Elasticsearch and Kibana stack, like there is for the other logging platforms. Elastic and Kibana are available there, but only as part of a general purpose cloud storage solution. Maybe we can use that somehow\u2026<\/p>\n\n\n\n

Improving our HTTP logs<\/h3>\n\n\n\n

Before we dig into how we can roll up something to use Elastic and Kibana, we need to first improve our general purpose HTTP logs. Since we\u2019re a Node shop, we are currently using the Morgan<\/a> package for compiling, with the default dev<\/code> format, and outputting our logs to stdout.<\/p>\n\n\n\n

\"\"\/<\/figure>\n\n\n\n

While these logs are great for local development, logging this format in production is less so. There\u2019s no dates, user-identifiable data, or information on the ReadMe project that was used, and we don\u2019t have Heroku\u2019s X-Request-ID header<\/a> anywhere. We can do better than this, and thankfully Morgan is extensible for us to log whatever we want by constructing some custom middleware and passing it a custom function:<\/p>\n\n\n\n

module.exports = inlet => {\n  return morgan((tokens, req, res) => {\n    const contentLength = tokens.res(req, res, 'content-length');\n    const responseTime = tokens['response-time'](req, res);\n    const referrer = tokens.referrer(req);\n\n    const metadata = {\n      inlet,\n      isEnterprise: req.project && req.project.isEnterprise(),\n      project: req.project ? req.project.name : undefined,\n      'x-request-id': tokens.req(req, res, 'x-request-id'),\n    };\n\n    return [\n      tokens['remote-addr'](req, res),\n      '-',\n      `[${tokens.date(req, res, 'clf')}]`,\n      `\"${tokens.method(req)} ${tokens.url(req)} HTTP\/${tokens['http-version'](req)}\"`,\n      tokens.status(req, res),\n      contentLength !== undefined ? contentLength : '-',\n      responseTime ? `${responseTime} ms` : '-',\n      `\"${referrer !== undefined ? referrer : '-'}\"`,\n      `\"${tokens['user-agent'](req)}\"`,\n      '-',\n      JSON.stringify(metadata),\n    ].join(' ');\n  });\n};<\/code><\/pre>\n\n\n\n
With a custom logger like this, we\u2019re now able to log a healthy amount of useful information.<\/p>\n\n\n\n
\"\"\/<\/figure>\n\n\n\n
But how can we make better use of these logs?<\/p>\n\n\n\n
Logstash<\/h3>\n\n\n\n
Logstash<\/a> is a server pipeline that can ingest logs from any number of sources, mutate them, and then send them along to another source (like an Elasticsearch cluster). The problem that we\u2019ve got is that, since we\u2019re on Heroku, we\u2019re still bound by its Logplex<\/a> routing layer. Thankfully, Heroku has a service called Log Drains<\/a> that allows you to configure a \u201cdrain\u201d on your logging firehose. This is our golden ticket.<\/p>\n\n\n\n
127.0.0.1 - [11\/Apr\/2020:00:35:14 +0000] \"GET \/ HTTP\/1.1\" 200 - 121.675 ms \"-\" \"Mozilla\/5.0 (Macintosh; Intel Mac OS X 10_14_6) AppleWebKit\/537.36 (KHTML, like Gecko) Chrome\/80.0.3987.163 Safari\/537.36\" - {\"inlet\":\"dash\"}<\/code><\/pre>\n\n\n\n
With our newly reformatted logs, we now need to figure out how we can ingest them, and only them, into Elasticsearch. This way, we aren\u2019t just replicating the same old firehose in a new datastore. There is a debugging tool,\u00a0Grok Debugger, that is wonderful at not only teaching you how the Logstash\u00a0Grok filter plugin<\/a>\u00a0works, but assists in constructing a Grok-compatible expression. A similar tool also exists within Kibana, and can be found under \u201cDev Tools.\u201d<\/p>\n\n\n\n
With the Grok Debugger, we\u2019re able to construct the following expression to match our new log format:<\/p>\n\n\n\n
%{IP:ip_address} - \\[%{DATA:date}\\] \"%{WORD:method} %{URIPATH:url} HTTP\/%{NUMBER:http_version}\" %{NUMBER:http_code} %{DATA:content_length} %{DATA:response_time} ms \"%{DATA:referrer}\" \"%{DATA:user_agent}\" - %{GREEDYDATA:metadata}<\/code><\/pre>\n\n\n\n
Some things to note here: Since we log a -<\/code> for content_length<\/code> and response_time<\/code> if we don\u2019t have it, we need to use Grok\u2019s DATA<\/code> pattern instead of NUMBER<\/code>. If we used the latter, the full log wouldn\u2019t get matched because – isn\u2019t a number. We could potentially clean this up by writing a custom pattern, but c’est la vie.<\/p>\n\n\n\n
From here, we can finally start to build out our Logtash pipeline:<\/p>\n\n\n\n
input {\n  tcp {\n    port => \"1514\"\n  }\n}\n\nfilter {\n  grok {\n    match => {\n      \"message\" => '%{IP:ip_address} - \\[%{DATA:date}\\] \"%{WORD:method} %{URIPATH:url} HTTP\/%{NUMBER:http_version}\" %{NUMBER:http_code} %{DATA:content_length} %{DATA:response_time} ms \"%{DATA:referrer}\" \"%{DATA:user_agent}\" - %{GREEDYDATA:metadata}'\n    }\n    add_tag => [\"readme_web\"]\n    remove_field => [\"date\", \"host\", \"port\", \"message\"]\n  }\n\n  if \"readme_web\" in [tags] {\n    json {\n      source => \"metadata\"\n    }\n\n    mutate {\n      convert => {\n        \"http_code\" => \"integer\"\n        \"http_version\" => \"float\"\n        \"isEnterprise\" => \"boolean\"\n      }\n\n      remove_field => [\"metadata\"]\n    }\n\n    if [content_length] !~ \"-\" {\n      mutate {\n        convert => {\n          \"content_length\" => \"integer\"\n        }\n      }\n    } else {\n      drop {\n        remove_field => [\"content_length\"]\n      }\n    }\n\n    if [response_time] !~ \"-\" {\n      mutate {\n        convert => {\n          \"response_time\" => \"float\"\n        }\n      }\n    } else {\n      drop {\n        remove_field => [\"response_time\"]\n      }\n    }\n  }\n\n  if \"_grokparsefailure\" in [tags] {\n    drop { }\n  }\n}\n\noutput {\n  if \"readme_web\" in [tags] {\n    elasticsearch {\n      hosts => \"yourElasticSearchCluster\"\n      user => \"username\"\n      password => \"password\"\n      index => \"readme\"\n    }\n  }\n}\n<\/code><\/pre>\n\n\n\n
Some things to note with this pipeline:<\/p>\n\n\n\n