LogStage: zero-cost structured logging in Scala. Part 2: Practical example

Maksym Ratoshniuk
Jul 21 · 5 min read

This article is completely about how to use logstage and how it could help you while development own software. If you haven’t read theory overview, please, read before start this one.

Agenda

We we will implement custom sink for out log entries and make some queries to fetch analytics from out logs.

So, imagine, that you need to flush log messages to ware house like Redshift and using some UI like Grafana, make some queries to fetch metrics or analyze some vulnerable parts of your API. To simplify working environment, let’s use PostgreSQL as database. So, please prepare:

  • scala 2.12;
  • postgres (docker or whatever you want);
  • postico (GUI for your database, if you prefer).

We use ZIO as the main framework for effect management. But it doesn’t matter right now. You can use whatever you want. As an API for postgres — doobie. These libraries doesn’t matter at all, the goal is to demonstrate customisations of logger.

Article structure

We will integrate logstage into real app step by step. Each step has own branch inside Github project, so don’t worry if you missed out something.

Domain overview

Imagine, that we need to write some platform that pulls data from multiple sources, process it and stores in S3 (routine, eh?)

And we would like to add some logs for our pipelines to have detailed flow while runtime.

simple data pipeline. incoming request invokes new job and it’s result submits somewhere

Our system is unstable due to unstable third parties, also, most of them have rate limiters and so on.

So, logs coverage would be good enough to track lifecycle.

Let’s implement some service that takes requests from incoming users to fetch some data from requested source.

Remember, we want to send out logs to console and database to querying the data.

First of all, let’s implement simple business flow and having complete app we will update it with Logstage.

For not wasting your time, I have already implemented basic application with domain logic.

Please, checkout on this branch, take a look at the code and will continue our journey.

Logstage init

Please, open a build.sbt file and add appropriate library dependencies for logstage.

libraryDependencies ++= Seq(
R.fundamentals_bio,
IzumiDeps.R.zio_core,
IzumiDeps.R.zio_interop,

//logstage
R.logstage_rendering_circe,
R.logstage_core
)

Let’s create simple trait WithLogger, which will contain logger and it’s configuration.

trait WithLogger {
val logger: IzLogger = ???
}

We need to implement our console sink with rendering policies.

We want to have colored messages and with plain text. After bringing all things together, we have a logger and we can use it.

trait WithLogger {
val textSink = ConsoleSink.text(colored = true)

val sinks = List(textSink)

val logger: IzLogger = IzLogger.apply(Trace, sinks)
}

Let’s replace after printlns inside AdReportService to be sure that logger is configured properly.

line 5 now invokes logger info instead println

Let’s put into info something and will execute our program.

Yeah! We managed to set up the logger within less than 2 minutes. Quite simple, doesn’t it?

Now you can see that our pipeline notify us about each step.

Let’s update functions of our service with logs to have more details about process. To simulate pulling and pushing let’s add some logged logic.

Here are updated methods for pulling and pushing data with logger:

Please note, that each pulling job requests user id and source id. So, we could filter our queries per each user, per each platform or event per user and platform together!

Let’s create custom logger inside this function and add key value pairs. Thanks for method granularity feature, we can do it very easy.

Method granularity helps us to define context of current flow and track the state for requested user or ad platform

Also, we can wrap into effect our logger to have better syntax and use the same effect as inside your app at all.

val granularLog = 
LogBIO.fromLogger[IO](logger(
"userId" -> userId.value,
"ad" -> adPlatform.toString)
)

And let’s put some messages over logic:

As you can see, now we have more detailed info for each context and even opening full text search during debugging could navigate you in your output without any complexity!

If you missed out something please checkout into this branch. It contains all code above. Next step is to write custom sink to flush entries.

DB logger sink

Let’s write our mocked sink that will simulate writing to db and rendering policy will be json.

Add doobie dependencies to your build.sbt:

//postgres
"org.tpolecat" %% "doobie-core" % "0.6.0"
, "org.tpolecat" %% "doobie-hikari" % "0.6.0"
, "org.tpolecat" %% "doobie-postgres" % "0.6.0"

Run your db and execute this statement to create table for logs:

CREATE TABLE logstage_out (
at timestamp without time zone NOT NULL DEFAULT now(),
payload jsonb NOT NULL
);
CREATE INDEX logstage_out_payload_json ON logstage_out USING GIN (payload jsonb_ops);

And create insert statement for our logs. Having Postgres, we can even put GIN index for our jsonb logs to optimize a little bit

Here is a code of your sink:

Also, don’t forget to add this sink for our logger:

val textSink = ConsoleSink.text(colored = true)

val dbSink: DBJsonSink = new DBJsonSink(blockingIO)

val sinks = List(textSink, dbSink)

Also, I have implemented batching to prevent frequent writing to DB.

Let’s run our app and let’s query rows from our table. Nice! All our messages are flushed inside the table.

Here is a content of destination table. You can find there jsonified logs and timestamps.

You can checkout this branch to have the latest changes and don’t forget to refresh your sbt after multiple updates of build.sbt file

Querying

As we managed to fill the table with real data, let’s query some result from it.

Use case 1: Query all actions for specific user and platform

select 
jsonb(payload->>'text')->>'message'
from
logstage_out
where
jsonb(payload->>'context')->>'ad' = 'GoodFellows'and
and
jsonb(payload->>'context')->>'userId' = '2'

And the output is:

my output is absolutely simple, but I hope you will have more details there :)

Use case 2: Select user ids who had rate limiter exception

select 
DISTINCT jsonb(payload->>'context')->'userId'::text
from
logstage_out
where
(jsonb(payload->>'text')->>'message')::text
ilike '%rate limit%'

And you have immediate output of unique items:

All what you need to track can be fetched easily from your logs.

Thank you for patience and I hope that you enjoyed with logstage and would be happy to use it. Stay tuned with our new tools and please welcome to contribute or request for issues and enhancements.

Welcome to a place where words matter. On Medium, smart voices and original ideas take center stage - with no ads in sight. Watch
Follow all the topics you care about, and we’ll deliver the best stories for you to your homepage and inbox. Explore
Get unlimited access to the best stories on Medium — and support writers while you’re at it. Just $5/month. Upgrade