- Let's get into a little bit now of design,
because one of the things I find that is lacking in
a lot of Go code is logging consistency.
I spent 30 years trying to figure out
how to combine error handling with logging
and I finally came to the realization that,
actually I tried to for 30 years, not try to combine it,
but separate it.
I always wanted to try to get the error handling
kind of separated in terms of frameworks and logic,
around how we log things, this separation,
and I really came to the realization
that you can't separate these two things.
That error handling and logging are just this one thing,
and we've gotta bring them together if we want
any consistency in them.
I'm always worried about consistency.
And so I always love asking this question to everybody
in the trainings that we do live, and that is,
if, let's say it's three o'clock in the morning,
and an error occurs in your software right?
An error occurs.
But the error is handled by the software,
and the program just continues to run.
There's no real hiccup.
Maybe there was for a second or two,
but it recovered, we keep going.
My first question is do you wanna wake up,
or do you wanna be woken up at three in the morning
because that just happened?
Remember nobody needs you,
the software just kept running.
The reality is that I don't wanna wake up.
I mean the software did what it's supposed to do.
It identified failure, it recovered, it keeps moving.
So I don't want to,
don't wake me up.
Let me sleep.
Now when I wake up in the morning and I get to work,
I wanna see some indication that there was a problem right?
I don't wanna be blind to it,
but I do wanna see it.
But the real question now becomes,
am I gonna spend time looking at the logs when I get in,
because right now again, it's not needed.
It was recovered.
Maybe on my dashboard for metrics,
I see that there was an error,
I don't know much more.
But the program kept going.
Here's the reality.
The reality is, is probably I'm so busy with meetings,
and other priorities,
I never go back to look at the logs
because it's no longer an issue.
It's not that I don't want to,
it's not that I'm not necessarily curious,
but it's just human nature to say,
I've got other priorities.
What I'm trying to stress here is that
we write applications that log a lot of things,
and most of the time we're logging as an insurance policy
to be able to find bugs when errors occur.
And I did that for a long time but the reality is,
is that there's too much activity on our systems today.
Our user bases can grow to a million people almost overnight
and so logging that much has a huge significant cost.
A lot of times logging is going to create
a large amount of allocations,
which is going to put a lot of pressure on your heap.
Now that's not unique to Go, but we are talking about Go.
So I want you to consider that logging is important,
but we've got to constantly balance signal to noise
in the log because if you're writing logs,
writing data to your logs,
that you end up never, ever reading or using,
you're wasting CPU cycles on something
that you could've been doing actual real work.
And it goes beyond just the CPU cycles of your process.
You're eating network bandwidth, disc I/O bandwidth,
other complexities that go through the entire system.
So during development I really wanna make sure
that we always have a good level of signal in our logs
and we're logging from a trace perspective
the bare minimum we need,
but then we're logging the errors in a way
that there's always enough context if we wanna take the time
or need to take the time to look at it.
And that's also been a big problem for me for 30 years.
How do you make sure there's enough context in the log,
both from a tracing perspective, bare minimal,
and then an error perspective and not duplicate errors
throughout a log and at the same time,
minimize those log writes and then, let's add more to it,
have a consistent pattern that we all can follow
and review during code reviews,
where we're doing logging the same way and it's not random?
Oh my God my head wants to hurt right?
All of these things.
You might find it hard to believe that I don't believe
in logging levels.
I've never been able to turn a logging level up in time
to get more detailed information.
So I'm not a believer in logging levels.
I tend to use the standard library log package quite a bit.
I will create my own logger and pass
that around the application but,
either I need this information or I don't,
and I make sure throughout my unit testing and any other
integration testing that I do that my logs have signal.
Now I wanna show you a pattern using
Dave Cheney's errors package.
Dave Cheney's error package is very, really nice,
and it gives us a consistent way to apply error handling,
apply logging and have code consistency throughout,
minimizing again a lot of pain.
But remember when I talked about handling an error?
That's a big thing.
Now that I can't separate logging from error handling,
what do I mean when I talk about error handling an error?
I mean really a couple of things.
When we talk about error handling what we're gonna mean is,
is that when a piece of code decides to handle the error,
it means that, that code is responsible for logging it
and logging in the full context of it.
It also means that code has to make a decision.
Can we recover or not?
If the answer is no,
then error handling means we shut down the app.
Either with the stack trace on the panic call or OS exit.
If we can recover,
then that code has to recover the application back
to its correct state and keep it going.
At the end of the day when that piece of code returns
it never, ever returns another error back up.
The error stops there.
Either the app is recovered or it shuts down.
But we've also logged the error.
That is error handling to me.
And this is what this pattern is going to be perfect
for with Dave Cheney's errors package.
So imagine this piece of code right here.
We're at the bottom of a call chain
and we make this call to thirdCall.
Some function above us makes a call to thirdCall.
And you can see here that thirdCall always fails.
It's failing with this custom error type called AppError.
We're using pointer semantics,
we're gonna store the address of AppError in there,
and we've set the error code to 99.
This is very similar to maybe like
a standard library function that is gonna return these raw,
or these true error values.
Now secondCall was the one that called thirdCall,
and you see our traditional mechanics in Go
where we're gonna use the if statement
to do the error handling right?
We're staying away from the else clauses.
Happy path in the first tab.
And so here we go, we call thirdCall,
we get back an error, interface value.
We ask is there a concrete value stored inside
the error interface?
The answer is yes.
When the answer is yes,
now the developer writing this code has to make a choice.
It's really boolean.
Am I gonna handle the error here, or not?
If the answer is handling the error here,
we deal with it like I said before.
But if the answer is no, I'm not gonna handle the error,
then there's only one thing you're allowed to do,
and that is wrap the error with context right?
We would prefer to handle the error,
the lower in the call stack we handle the error,
the better opportunity you're gonna have for recovery.
But in this case the developer has decided,
no we're not gonna handle the error.
Think about this.
I don't have to worry about logging anymore
and I don't have to worry about recovery anymore.
All I worry about is the wrap call.
Now the wrap call is interesting because it does two things.
At this point remember that we've gotten an AppError.
Here it is, this is our AppError,
and our AppError is already wrapped against
this error interface value.
Now this is error, right?
Wrapping the AppError.
But what wrap is going to do now,
is wrap context around what we have.
And there's two types of context.
There's gonna be call stack context
and there's going to be user context.
The call stack context is going to take a,
where we are in the code at that line of code
that we're doing the wrap.
We now know exactly where we are when this error occurred.
And we're also now also gonna be able to add
some user context.
In this case I'm just indicating that secondCall
was calling thirdCall.
So we're gonna get call stack and user context
built in there.
Now we take this error, we wrap it,
and we send it back up the call stack.
And when we do, firstCall now is involved.
Remember firstCall is calling secondCall
with the parameter of i.
Now an error occurred, we know that right?
We know that secondCall returned this error.
Well guess what?
firstCall now has to decide am I gonna handle the error?
If the answer is no, then you only have one choice.
We wrap the error again with that context,
our user context and our call context.
Notice this time our user context is showing the parameters,
or the values we passed into secondCall.
This is brilliant stuff.
You can share any context you need and if you get bugs
and the context isn't enough,
this is what you're gonna be improving, the context.
If I'm writing a database type of app and I don't have
a security issue writing queries to the logs,
that would be a query so I can copy and paste it
out of the log and run it directly.
Here I love showing what the input was,
because I'm not gonna get that in the call stack context,
but at least I can see what values were passed.
That could really help.
So I've got, this is the original error right here.
This is one wrap right here.
This is another wrapping right there.
And we go to main.
Now main made a call to firstCall,
it gets back the error.
It says, is there a concrete value stored inside
the error interface?
There absolutely is.
Therefore we now come into this.
Now the mechanics that I showed you on the case,
doing the generic type assertions, guess what?
We get to continue to do that because of the cause function.
What's brilliant about the cause function,
is it knows how to unwind this down and get us back
to the root error value.
And now we're gonna type assert against
the root error value,
and when we do that we can do the case on line 30.
But I think what's even more powerful is this.
If you're using the standard library fmt or log packages,
like I do, if you put a %+v in the formatting, guess what?
The full stack trace and context of this whole thing
gets logged to, in this case,
standard out or standard error,
wherever you're logging.
And if you just do %v,
then you're just gonna get your user context.
%v just gives you the user context.
%+v gives you both.
Now I wanna show you this running so you see it visualizing
it right here.
Let me copy the path and get us over into our terminal.
And what I'm gonna do is build this program
and then I'm gonna run it.
And I want you to notice the output.
Now the first output you're seeing,
is when we did the %v.
We're doing the %+v.
And what you see here is a full stack trace,
here's the AppError context state 99.
And we can see stack traces from the different levels
of calls that we were making in the app.
Here's firstCall right?
So that's runtime, main,
main all the way to firstCall.
There it is.
And then we've got our context of what we've passed in,
and here what we're seeing is the full context
from main to firstCall to secondCall,
and then the context to thirdCall.
So we can see individually how these different layers
that we got from our wrapping, came in.
And then I can use just the v without the +
and what you see now is just the context, the user context.
So I can look at a stack trace from any point
in the call chain and then I can also look at
just the user context right?
So we see here firstCall line 51.
Let's go to line 51.
Look at that.
We know that there was failure on that call to secondCall,
that's where we were, inside of there.
Again if we look at firstCall 52,
we know that that's where the wrap call happened.
We got a tremendous amount of context here
about where we were and we don't have to worry
about logging all the way up right?
We're not gonna separate logging from error handling.
It's just one thing.
So from a user perspective remember
this is all we're gonna have to now remember.
But from a developer perspective,
what we're gonna just say is,
oh my goodness, an error called.
Are we gonna handle it or not?
If we're not gonna handle it, we wrap it.
If we are gonna handle it,
then we deal with it.
We log it and then we make decisions
about whether we can recover or not.
This is in a fantastic pattern and I really again,
want you to,
I want you to not feel like you've gotta log everything
as an insurance policy.
Signal is everything in logging because logging
costs you a lot.
It's going to cost you lots of allocations,
so the logs that you're writing better be worth the cost.
They better be truly information you need
if there is a problem,
and information from a tracing perspective
to allow you to know that the system is healthy.
Don't forget that we have dashboards.
We have metrics.
I don't like writing data into the logs.
I'm not a big fan of structured logging because for me,
logs serve the purpose of being able to find and fix bugs,
but that's me.
And I rather use my metric systems and my dashboards
for those data points,
and try to tie that stuff together.
So I really want you to look at Dave Cheney's package.
You'll find it in GitHub under pkg errors
and this pattern is something that we use at Arden,
and a lot of people that are my clients that I teach use,
and it's been very, very effective for us.