00:04
first talk after lunch I wonder how many
00:07
of you are you know like energized
00:08
versus
00:11
sleeping all right let's do this so I
00:14
want to start with a story our story
00:16
starts uh a couple years ago back then I
00:20
was part of a team working on a small
00:22
internal application in a previous
00:25
company one day we got paged by our
00:28
infrastructure team because our workers
00:30
servers were at 100% CPU usage and had
00:33
been that way for a couple
00:35
hours something was wrong this was
00:38
related to our workers so of course the
00:40
first thing we do is we open our
00:42
sidekick dashboard and we saw
00:46
this yeah that's right over 800,000 jobs
00:50
in CU this was a small internal app so
00:53
this was not expected at all we fixed
00:56
the issue I don't want to get into the
00:58
details here but we wanted to figure out
01:00
why this happened so this wouldn't
01:02
happen again so someone in the team
01:04
asked the natural question hey can we
01:07
check our
01:08
logs and when they said that the first
01:11
thing that popped into my mind was
01:12
something like
01:16
this so we do have logs but there're
01:19
piles of raw texts that are hard to use
01:22
and to find anything in it was painful
01:25
and far from the best
01:27
experience the second thing that pum in
01:30
my mind is was this site I read a couple
01:32
months prior and that came back to haunt
01:43
me so yeah our logs are trash this hits
01:46
too close to home now that keep me
01:50
thinking why trash why can't we use them
01:54
to get actionable insights that's why
01:56
they're trash because we can't do that
01:58
so what did what charity me meant was
02:02
that our logs were not data they're just
02:05
piles of raw text with no
02:07
value but that got me thinking what if
02:10
they were What If instead of piles of
02:13
unstructured texts we could treat our
02:15
logs like data and use them to get
02:17
valuable and actable
02:20
insights hi my name is Yousef and I want
02:22
to talk to you about turning logs into
02:26
Data I am a senior engineer at workato
02:29
where we create a product for companies
02:31
to automate their business processes
02:33
without writing any
02:36
code like all of you I love writing Ruby
02:39
I've been coding in Ruby almost my
02:41
entire professional career and I
02:43
especially enjoy working on developer
02:45
tools because I believe that coding
02:48
should never be a chore and that making
02:50
developers more productive is is just a
02:53
joy to work on and it's actually my
02:55
second favorite
02:57
hobby my second because I said say
02:59
second because my first Passion is
03:01
photography I rarely go out without my
03:03
camera and if I'm lucky I get back with
03:06
some shots that I'm happy with such as
03:18
these So speaking of
03:24
logs our agenda for today we're going to
03:26
start by looking at the default raise
03:28
logs which question question they can
03:30
help us answer and which ones they can't
03:33
in the second part we're going to to
03:34
going to introduce more structure into
03:37
them and shape them into data and
03:40
finally we're going to see a Showcase of
03:42
the kind of insights we're going to get
03:43
from
03:44
them so let's start by looking at the
03:46
default race logs and to get logs we
03:50
have have to first run some codes so
03:51
there's a basic action that everyone
03:53
should be familiar with so just an
03:56
update user user update action you take
03:58
an user you find find them you update
04:01
and then you redirect to an
04:04
action so the default race logs look
04:07
something like this in a very simplified
04:09
case so we have five lines output total
04:13
and uh we
04:15
do see we can
04:17
this we start by like the request starts
04:21
and then we output a line then we start
04:23
processing the request and we output a
04:25
second line here and then we also output
04:28
the parameters uh which like the user
04:31
the country the local like everything
04:33
that is in your application then we
04:35
redirect so we also output something
04:37
here and then at the end we have a
04:39
little summary of the
04:42
request so these are the logs we already
04:45
we all have by default so what kind of
04:49
what kind of questions we can ask these
04:51
logs so we can
04:54
ask how many patch requests do we
04:57
process per day
04:59
we can
05:00
ask which controllers are our
05:04
busiest
05:06
or what's our rate of 404
05:10
responses but are these really the
05:13
questions we want to ask as one French
05:16
philosopher once wrote judge a man by
05:19
his questions rather than by his
05:22
answers so I went to French school so by
05:24
law I have to quote volter at least once
05:26
a month or they come for me
05:31
but in all seriousness I find that
05:33
thinking about questions is often more
05:35
valuable than getting the answers so
05:38
what are the questions we want to
05:41
ask so we want to be able to ask which
05:44
requests did this specific user
05:47
perform
05:49
or why did we suddenly enq a large
05:52
amount of
05:55
jobs or how many users are using this
05:58
Legacy API end points that we've been
06:00
wanting to retire for a while and what
06:03
do they all have in
06:05
common or another question that's a bit
06:08
more complex is is this feature flag
06:10
affecting database
06:12
performance on some revision of our code
06:15
in Us East one so notice that this
06:18
question is about correlating data from
06:20
completely different parts of our stack
06:22
so the application the database kits and
06:27
infrastructure so why can't we answer
06:29
this question with our logs
06:31
today my my theory is that there's four
06:35
main issues with these logs so first
06:39
they're
06:40
multi-line so it's okay when we see
06:42
things like this it's relatively okay
06:43
because when when we process a single
06:45
request but then when we aggregate the
06:47
logs from multiple servers which we can
06:49
have hundreds of they all become
06:51
intertwined and it gets impossible to
06:53
actually make sense of
06:55
them second they're not structured
06:58
they're made for human eyes but it's
07:01
hard to analyze programmatically and
07:03
like actually get patterns from
07:06
them third they're missing the main data
07:10
so there's no concept of user or like
07:12
revision or AWS Zone there's nothing
07:16
here so there's no nothing we can query
07:20
against to analyze the
07:22
data and finally they're uncorrelated
07:25
between systems so meaning each systems
07:28
and each apps logs only refer to that
07:31
single system and we can't correlate for
07:34
example the logs that are output from a
07:36
worker from and from
07:40
web so can we fix this at least what we
07:43
have with these four issues is that we
07:45
have a very so we have four problems we
07:48
can tackle them one by
07:49
one and that takes us to second part of
07:52
the talk where we'll take all these four
07:54
points and see how one by one we can fix
07:57
them so our first problem was that logs
08:00
were
08:02
multi-line this is what we saw before so
08:05
I call them print as you go logs so as
08:07
the request goes through the rail stack
08:10
it outputs log lines for each step so
08:14
this gives us a kind of a story for the
08:16
request life cycle it's telling us oh I
08:18
started and now I'm processing and then
08:20
I'm redirecting and I'm
08:23
finished but that's not interesting to
08:25
us what we want is we want a summary of
08:27
that request we want to have all the
08:29
information all at
08:31
once so what we do is we can consolidate
08:35
these these logs and it's actually
08:38
pretty easy when you're doing Ruby so
08:40
there's a gem for that you can use log
08:44
Rage which is the OG or a ra semantic
08:47
logger uh which is more
08:50
advanced both of these will give you
08:53
something like this so all the request
08:57
goes through the stack there's nothing
08:58
output and just before the request
09:01
exits that it outputs one single line
09:05
with exactly the information that we had
09:06
before so we have the methods the path
09:09
format everything that we had before but
09:12
Consolidated on a single line at the end
09:14
of the
09:15
request so we fixed the first part
09:18
problem number two those logs are
09:21
unstructured when we have unstructured
09:23
logs we can structure them so what we
09:26
can do to enable structure logs is uh
09:29
both the gems I mentioned before have a
09:31
setting for uh formatting logs in a
09:33
certain way so here we're going to use
09:37
the Json formatter for log
09:40
R and what it does is that instead of
09:44
having this a key value pair that we had
09:46
before we have a Json document as an
09:49
output uh it's a bit hard to read here
09:52
so I just expand it but it's it's still
09:55
one single line that's
09:57
output and here we have yeah it's key
09:59
value pair is a Json document we all
10:02
know that in that has all the
10:05
information from all the request that
10:07
just came through our stack and we can
10:09
even structure information inside like
10:11
this parms here where we have a nested
10:13
Json document so we can actually have
10:16
structure so this is a key Point what we
10:19
just did here is we turn logs into
10:22
Data if you're going to remember one key
10:25
point from this that's it structured
10:27
logging turn turns log into Data by
10:30
outputting one single structured line at
10:33
the end of each request you can think of
10:36
them as an events that the uh that the
10:39
request produces an event
10:42
summary so we can continue by talking
10:46
problem number three logs are missing
10:49
data so we can do is we can enrich our
10:54
logs because now they're structured but
10:55
they only contain generic information
10:58
they don't know anything about our app
11:00
so we can enrich them with domain
11:03
information I'm very thankful that the
11:04
screen is
11:06
big so we can have like for example
11:08
Environ information from the environment
11:11
here so the we can pass the proc type
11:13
the revision or the a region
11:16
here we can have the extra data from the
11:19
request like the request ID and the user
11:23
agent or we can have anything that you
11:25
can think about in your
11:27
controller so we can can output the
11:30
local we can output the current user
11:33
information and anything that is
11:35
relevant to your specific
11:39
application and we get something like
11:41
this at the end it's truncated but it's
11:44
exactly what you expect so we have all
11:47
the information filled in the Json
11:49
document we had the pro type revision
11:52
local and I want to spend some time
11:56
here uh with a couple warnings
11:59
it's a bit too easy to shoot yourself in
12:01
the foot doing this there's two points I
12:03
want to
12:04
address the first one is
12:09
performance so only log information that
12:11
is cheap to compute so environment
12:13
variables are
12:15
okay objects you already have in memory
12:17
are okay but don't put extra database
12:20
calls to enrich your logs because the
12:23
overhead there can be
12:26
significant and the second one which a
12:28
bit more pricious
12:30
is accidentally exposing private
12:32
information it's way too easy to
12:35
accidentally log sensitive information
12:36
to
12:37
logs and actually if you didn't do
12:41
anything to your rails app by default
12:43
you're probably outputting sensitive
12:45
data to your logs because we're
12:46
outputting the params object by default
12:50
and that can contain name emails birth
12:52
dates Social Security numbers because
12:55
you have the user update action and
12:57
there's a lot of stuff in there
13:00
so what you can do is if you're really
13:03
strict about that don't output the parm
13:06
object or what you can do is that you
13:09
can uh use the axis4 has a feature
13:11
called parameter filter and it can be
13:14
used to filter some sensitive data for
13:16
example if you know that all your params
13:18
are okay but maybe name and email are
13:20
not okay you can have an blocking list
13:25
there and I want to end this section by
13:27
just showing you one example of this
13:29
going wrong in the
13:32
wild so 5 years ago Facebook was caught
13:36
storing user passwords in plain text and
13:40
this is not because they were storing
13:41
the data itself in plain text in their
13:43
database they're too smart for that but
13:46
because they were logging them as part
13:47
of their
13:49
parameters so yeah be careful about
13:54
this and lastly we want to check problem
13:57
number four where the logs are
13:59
correlated between systems so what we do
14:02
again when we have uncorrelated logs we
14:04
can
14:06
correlate so correlation means linking
14:08
logs between different systems and as
14:11
such it's like we
14:13
can is it all depends on your systems so
14:16
it's hard to give general advice here
14:19
but I want to show you two examples of
14:21
corating logs just for
14:24
inspiration so the first example is in
14:26
the context of distributed systems
14:30
sometimes you have dozens of
14:32
microservices calling each other just to
14:34
answer one single HTTP request I don't
14:37
know why you would do that
14:39
okay so how do you track this how do you
14:41
track who calls whom and like which
14:43
requests were done
14:45
to answer this one
14:47
request so one way is to have the first
14:50
entry point service maybe the Gateway
14:52
generate a unique ID which is usually
14:54
called correlation ID and then you pass
14:57
it as an HTTP header to any subsequent
15:00
request so this is the header that we
15:04
passing and then any any system that
15:07
gets this correlation ID will output it
15:10
again in their logs so that means that
15:13
if you filter by your logs by
15:14
correlation ID you get to see all the
15:17
requests that are in in the
15:22
chain a second
15:24
example is how to correlate jobs and web
15:27
requests
15:29
so sidekick has the concept of
15:30
middlewares where you can add metadata
15:33
to jobs when they are ened so what we
15:36
can do is you can have this ined by
15:40
request
15:41
ID U ID that you you add to the job
15:45
request to the job uh when when it's
15:48
seced
15:49
automatically so that whenever you have
15:51
a job that's executed it will output
15:54
this request ID so you can trace exactly
15:56
where the job came from
16:01
so to
16:02
recap we have Consolidated our logs into
16:06
one line per
16:07
request we structured them into Json
16:10
documents we enriched them using the
16:12
main data and we correlated them between
16:16
our
16:17
systems and that gives us something like
16:19
the log line right
16:22
there so what
16:25
now this the fun part of the
16:27
talk we we're entering the third part of
16:30
our agenda where we'll see how we can
16:31
analyze our logs in different
16:34
ways logs are now data so we can treat
16:37
them as such and what we do is we first
16:41
ingest them into our data analysis
16:43
platform of choice there are many to
16:45
choose from I do want to give a special
16:48
me mention to better stack who's
16:49
sponsoring this
16:51
conference you can find them in the
16:53
booth outside and they'll be happy to
16:54
talk to you about
16:56
this but for this presentation I'm going
16:58
to be using kibana which is based on
17:00
elastic search sorry but
17:04
stack they're not paying me for this I
17:06
just uh like their
17:09
product so this allows us to go from
17:11
this one log line to this it's a
17:15
document in a
17:16
database and from this
17:21
nonsense to this it's a queriable
17:23
database of all our
17:27
requests so back to our question
17:28
question
17:30
s we asked we wanted to ask which
17:33
requests did this specific user
17:36
perform now we're going to see how we
17:39
can do this in uh using this
17:43
kibana so we're going to start from
17:46
having all the
17:48
logs 24,000
17:51
here and we are logging the user ID so
17:53
we can use this to filter the requests
17:56
that come from that user ID
17:59
there you go 20 hits not only that but
18:02
we can
18:03
also select different fields that we're
18:06
interested in for example we want to see
18:08
which controller which action and what
18:11
the duration of the
18:13
requests and now we have a nice table
18:15
here where we see for each of the 20
18:17
requests that the user made exactly
18:19
which data we wanted we wanted to see
18:32
so next we wanted to ask why did we
18:35
suddenly enue a large amount of
18:39
jobs
18:41
again we're going to start from Ora
18:44
logs and we're interesting jobs so we're
18:46
going to start by filtering the sidekick
18:49
logs
18:52
only and here we can visually see that
18:55
this app doesn't have a lot of activity
18:57
except here
19:00
so we're going to try to focus on those
19:04
those log lines
19:06
there we know roughly when they
19:11
appeared and then we're going to try to
19:13
look how can we correlate all of these
19:15
things remember we added this ined by
19:19
request ID to our logs before to our
19:21
sidekick logs so we can add it to the
19:27
table then we can and see if we can find
19:29
anything that's
19:33
weird and here we we see a lot of jobs
19:36
that have the same request ID that in
19:41
them that is
19:43
fishy but we have something we have the
19:45
request ID so we can just look for
19:51
it you find it
20:00
then we can see which controller
20:02
maintenance tasks controller okay action
20:05
start daily cleanup that sounds
20:08
weird so now we know exactly what
20:10
happened and why we ined all these jobs
20:13
but we can do more we can see who in
20:15
this
20:16
jobs and you can get the user email and
20:19
user ID from
20:23
there and of course it's super admin so
20:25
me
20:30
so yeah from our logs we were able now
20:33
because we had all the data there to get
20:35
actionable
20:37
insites and know why this problem
20:39
occurred and what we can do about
20:43
it we're going to
20:45
continue how many users are using this
20:48
API endpoint this Legacy API endpoint
20:50
and what do they have in
20:52
common so now instead of seeing like the
20:55
logs in a list we're going to visualize
20:58
them
21:02
so we're going to first try to see how
21:04
many users we
21:05
have so we want to count the unique
21:10
users by filter the unique request by
21:13
user
21:15
ID and we got the number 109 but that's
21:18
for all are up we want to see exactly
21:21
who's who's hitting the Legacy
21:24
controller so you can filter by the
21:26
Legacy things controller
21:30
and there you go we have seven users
21:32
that are using this Legacy
21:35
controller but we want to do more than
21:37
that who are these users and what do
21:40
they have in common so that we can
21:42
actually retire this
21:45
endpoint so we do the same thing but now
21:48
instead of just a number we're going to
21:49
do a pie
21:51
chart so we're going to
21:53
count those are all of our
21:56
requests same thing so before we're
21:58
going uh filter by
22:05
controller and then we're going to slice
22:07
the data by guesses let's see maybe they
22:12
all come from the same AWS
22:15
region no they all come from all
22:21
over so maybe they're coming from like
22:24
they the request are in specific format
22:27
no we have both HTML and Json
22:29
on maybe they're using specific
22:34
language
22:36
nope maybe I don't know user agent is
22:40
the
22:45
same there we go so we figure out that
22:48
all our requests that hit are hitting
22:50
the Legacy controller is are coming from
22:52
our old mobile app and we can take the
22:55
iPhones away from people so we just have
22:57
to retired
23:00
them and this our last question remember
23:03
this is one this the one that went like
23:05
all across the stack is this feature
23:07
flag affecting the database performance
23:10
on revision something in Us East
23:13
one and what we did when we enriched our
23:16
data like our log data is that we kind
23:19
of collapsed all of these St this places
23:23
in our infrastructure into one single
23:27
level so this this is now actually
23:29
pretty easy to do so it's going to be a
23:31
bit
23:31
faster so you want
23:33
to have a graph of the database front
23:39
time filtered by revision
23:44
revision and AWS
23:52
region and we want to splice it by is
23:55
the feature flag enable or not
24:06
there we go we see that clearly if you
24:08
enable the feature flag the database
24:10
performance takes a
24:12
hit so structure logs are
24:17
awesome by turning logs into Data we can
24:20
use them in new ways we can slice and
24:23
dice the data to explor patterns
24:26
answering new questions without changing
24:28
any
24:29
code these questions can range from the
24:31
need and Hast stack kind of questions to
24:35
long-term
24:36
trends you can almost think of them as
24:39
technical business intelligence for
24:42
developers and I can guarantee that once
24:44
you try this you can't go back to
24:47
tailing
24:50
logs so we're nearing the end of the
24:53
presentation so I wanted to mention just
24:55
a couple final words about structure
24:56
logging in a larger context
24:59
first is this is not new this practice
25:02
has been around for
25:05
years Heroku has that in their
25:10
guides stripe has a blog post from 2019
25:14
calling them canonical log lines but
25:16
it's just the
25:17
same and even a couple months ago there
25:20
was this blog on blog post on hyper news
25:23
with like white events is what you need
25:25
white events is just this structured
25:27
logging
25:28
they call them wide events because
25:30
they're theories that you can you should
25:32
try to put all the data you can in them
25:34
so the Json documents get pretty
25:38
big and there's this even this quote by
25:41
DH stting that Shopify and 37 signals
25:44
have been using in-house structure login
25:46
for a long
25:47
time so this is not new at all it's just
25:50
it's not a very well-known feature out
25:52
of outside of larger
25:54
companies so we are lagging behind
25:58
we the Ruby and the whales Community are
26:00
lagging behind in the adoption of this
26:02
practice other communities like if you
26:05
turn into the Java communities and the
26:07
goine communities they have integrated
26:09
this into their tooling a while ago and
26:11
it's almost a given for new
26:14
projects but in ra project you still
26:16
have to do some work to get this and you
26:20
only see that happen in mature
26:23
projects but let's fix
26:26
this rails builders
26:28
if you're building anything try this
26:31
approach try structure loggings use it
26:34
and spread the word about it I guarantee
26:36
you will not regret
26:38
it gem maintainers if you have a gem
26:41
consider adding an optional structured
26:43
login option for your gem so that all
26:46
your logs can be
26:48
ingested in such
26:51
systems by the way this applies to rails
26:54
too the DHS codes I just gave you it
26:57
actually comes from an issue that was
26:59
created late last year there was a
27:02
proposal to add structured login
27:03
directly into
27:05
rails I'm very happy about
27:08
that but we don't have to wait in the
27:11
meantime we can only use structured
27:13
login today and start asking our logs
27:16
the questions we want to have answered
27:18
instead of merely the ones we
27:20
can thank you
