Searching through JSON logs with Node.js
Tags: webdev, javascript, node, postgres
Published: 2023-03-04 20:29:44

---
title: Searching through JSON logs with Node.js
published: true
description: A story of my practical experience of searching through a terabyte of web services logs on my laptop with Node.js and Postgres
tags: webdev, javascript, node, postgres
cover_image: https://dev-to-uploads.s3.amazonaws.com/uploads/articles/jx4quijd5184d6p9dggm.jpeg
---

I had to do a search through logs from our backend on my laptop. We have about 40 various web services that write logs in JSON format. And these logs together with logs from sidecars then streamed to Sematext (which is a managed [ELK](elastic.co/what-is/elk-stack) service). After a retention period logs got chunked into LZ4 compressed text files and backed up to an AWS S3 bucket.  

The problem? There're a lot of logs. Every such archive is ~1 MB is size. It contains about 5,000 of JSON records. 1 month of logs is about 100k of files and about 100 GB in size.

Unfortunately, there was no established process on the project. A couple of team mates had experience with logs a year ago and all they did was: download, unpack, grep.

In my case grepping wasn't the best option as I needed not only to find the specific request (log), but also the review its distributed trace and context.

I had 2 options on my mind: local `ELK` and [lnav](https://lnav.org/). I tried to google about how to quickly run ELK in Docker locally (I had no prior experience in setting ELK up), but haven't found good tutorials. I believe they exist, but I also was thinking about possible caveats.

Our logs are not unified: some services populate different field names like `status` vs. `statusCode`, and they may also be of a different type (number vs. string). Writing ElasticSearch preprocessors in `painless` is not so painless. And not everything could be done there. I know this as I was setting up Sematext Pipelines before.

So, I've downloaded 112GB of logs for 1 month and tried to tame `lnav` instead. Unfortunately, `lnav` couldn't open my `lz4` files because of some `unexpected end of stream` issues. `lz4` command line utility produces such errors as well, but still decompresses fine. But uncompressed files are 8 MB instead of 1 MB (112GB --> 896GB?). I tried on an uncompressed directory with just couple of files and it was overwhelming. I was reading through `lnav` docs when saw that you may also define a scheme and load logs into an internal SQLite database.

This is also where I saw a new shiny bicycle 🚲 But at least it could be *fun* in comparison with boring docs...

I'm a JavaScript dev: loading/parsing files is easy. I also could easily transform all logs to a unified format and throw away fields that I don't need like Kubernetes labels, etc. And our team is used to Postgres. If I upload all the data into a local DB, it might be very convenient. And I could sort everything properly, because logs in files are sorted in order of streaming from multiple sources, not by actual timestamps. So many benefits!

![How hard can it be](https://img.memegenerator.net/instances/56610968.jpg)

I settled on a very simple streamed pipeline:

```text
glob --> lz4 --> createReadStream --> readline
  --> transform --> filter --> insert
```

Creating CLIs with [yargs](http://yargs.js.org/) is a piece of cake. For LZ4 there is a streaming implementation on [npm](https://www.npmjs.com/package/lz4) which is a single  function and also happened to decompress my files without any errors. Everything else is out-of-box Node.js.

Transformation itself is just creating a new object based on parsed JSON. I know all 12 fields I will need. Creating a DDL for Postgres table didn't took much time as it's structure is the same as TS interface I already defined.

Interestingly, every log has a natural Primary Key, because logs are in files, which are static. Backups only add up, no files are modified. We could use `file_name` + `line_number` to identify any log record. Why do we need this? For an incremental workflow. Inserting into a DB is very slow and is the main bottleneck. Of course, we could optimize it by using multi-value insert, disable triggers and constraints, etc. But I only disabled WAL for the table (as I will not modify row and can restore data) and decided to load data gradually:

1. Filter incoming records in JS to find the place in time where your issue(s) happened. For example, load only DELETE requests.
2. Use SQL GUI to view/filter this data, sort by time.
3. When time spans of interest are identified, tweak glob expression to load additional files for these time spans without filtering or with a different filer.
4. Repeat.

Filter is a function in the TS file, which gets a transformed record and returns a boolean. If it's `true`, the tool executes an `INSERT` command with Postgres' extension `ON CONFLICT DO NOTHING`. So, even if you try to load the same file multiple times, you would not get duplicate records thanks to the natural PK.

It looks like this:

```sh
$ yarn ts-node ./log-loader.ts './aws/2021/02/**/*.lz4'
...
Loading file [159432/159438]: ./aws/2021/02/24/21/20210224T214041.318Z_5950e47a96ee741360bedbf6153ab069.json.lz4
...
Done, 159,438 files loaded, 1,095,380,480 lines parsed, 241,584 records added
✨  Done in 7572.51s
```

Time varies greatly with the number of inserts. Still, it's not exactly instant, but is fast enough for my use case. After a couple of iterations I got proper distributed traces for several requests of my interest in the DB and found who called what and why. I saved time not in *grepping*, but in a nice GUI to look at final logs and understanding call stacks.

A couple of month gave me 397,785 final rows. SQL queries work quite fast even without indexes: a search by URL prefix took only 2.278 sec.

Actually, loading local files is not enough. I have only 512  GB on my laptop SSD and all it can fit is 3 month. So, for some cases I had to load data directly from AWS S3. It is slower for multiple runs, but I couldn't use external drive or other computer.

Adding S3 support was very easy too. I just extracted `fs/glob` code into a `fsAdapter.ts` and added `awsAdapter.ts`. If you specify `--aws` option, then the positional argument of CLI is treated as bucket + prefix and the AWS adapter is used. From AWS client you only need `listObjects` and `getObject`, after which you obtain the same Readable stream as you had with the file system.

Next time I might try to set up a local ELK to get a similar experience to not yet backed up logs (nice UI). As for the current project... I'm curious how many years the `log-loader` will be in use by my colleagues if the *manual* way lasted for almost 6 years.