February 20th, 2023 × #logging#debugging#visibility
Logging
Wes and Scott discuss the value of comprehensive logging in web development and some best practices.
- Logging overview and basics
- Sentry sponsor ad
- What logging is and basic usage
- Why log things
- Logging vs error handling
- What to log in development vs production
- Importance of timestamps in logs
- Other useful log metadata
- Logging request data
- Logging descriptive messages
- Avoiding logging personal data
- Log levels from error to verbose
- Production vs development logging
- Logging security events
- Logging bot access attempts
- Logging rate limiting
- Log storage and retention
- Third party logging services
- Using logging libraries like Winston
- Custom middleware for logging
Transcript
Announcer
Monday. Monday. Monday.
Announcer
Open wide dev fans, get ready to stuff your face with JavaScript, CSS, node modules, barbecue tips, get workflows, breakdancing, soft skill, web development, the hastiest, the craziest, the tastiest web development treats coming again hot. Here is Wes, Barracuda, Boss, and Scott
Scott Tolinski
CSD.
Scott Tolinski
Welcome to Syntax.
Logging overview and basics
Scott Tolinski
On this Monday, hasty treat, we're gonna be Talking about logging.
Scott Tolinski
Logging is something that, well, we sometimes do just to debug. And many times, people overlook the usefulness of having Really good logging within your application inside of both production and development environment. So my name is Scott Talinski. I'm a developer from Denver. And with me, as always, is Wes Boss.
Wes Bos
Hey. How's it going? Not too much. I, I've been sort of taking my, like, logging a little bit more, seriously in the last couple months just because I I had some, like, gremlins In my app that I couldn't figure out, like, where it was coming from and and what would even cause this request and and whatnot. And, like, I just didn't have enough insight into like, it Wasn't errors or crashing or anything. It was just, like, couldn't figure it out. You know? So we'll talk about, like, what that is. So I I sort of went through and updated my logging. I'm still not like some of the stuff in this episode where I talked about I'm not using it. I'm mostly still just a console logger. But, Well, yeah. Let's let's get on into it. Yeah.
Wes Bos
Let's let's talk about our sponsor today, which is Sentry. Sentry is the They're an exception.
Wes Bos
They do so much more of that. They do performance, they do profilings, and now they are getting into session replay, which will allow you to literally see what the user had done in your application to to trace through what's going on. So it's It's actually kind of funny that we talk about logging because a lot of the stuff that Sentry does makes it so that you don't necessarily have to piece together logs. And we'll talk about what the difference is between those types of things.
Sentry sponsor ad
Wes Bos
But check it out at century. Io. Use coupon code TASTE That is going to get you 2 months for free. Thank you, Century for sponsoring.
Wes Bos
All right, let's get into it. What You wanna give us a start of, like, why and what is logging?
Scott Tolinski
Yeah. So at, you know, at its very most basic, everybody has probably We tossed a console log into their code at some point to output something either on the client side log or your server side log, And these can be used primarily you know, we often just throw it in for a quick debug or something like that. But You also probably have seen logging from other frameworks or other things that you've used where you're it. Automatically just getting some things coming in on your your console explaining what's happening maybe at some given point. Maybe it's, explaining the requests that are coming in. Maybe it's just saying, oh, you know, a message came in at this time or whatever. It depends on what system and what type of logging is enabled in these types of things. And And many even, like, CMSs have, like, baked in logging as well outside of the JavaScript context.
What logging is and basic usage
Scott Tolinski
But in At the end of the day, logging is basically giving you visibility to some action that is happening it. On your server or your client, depending on how you're doing this. But at its very most basic, it's a console log. It's a, I got here, but Yeah. It's more complex. It's a a git request was hit to this specific URL at this time, And it took this amount of seconds to resolve or did not resolve or whatever.
Why log things
Wes Bos
Why might you wanna log something? Logs Are often helpful as sort of a treasure trail to figuring out what happened, If you need to, everywhere from just you, the developer, needing to figure out, okay, well, that shouldn't have happened or I need to figure out why somebody specifically hit this URL with what data and it caused them something.
Wes Bos
You can log out that information if you just wanna see what endpoints are are being hit with what specific data. You can log that, or something just as simple as, like, an email was Specifically sent. We'll go a little bit more into the different types of logging. So it helps piecing together things, helps us find ability.
Wes Bos
Worst case, I've certainly not had to do this before, thankfully, but I've heard of things crashing databases going down, whatever. And often developers have to, they don't have the data of like maybe 10,000 sales went through. They can sometimes piece that information back together or at least the important bits, via logs They can parse out their logs and and recreate that data in the database.
Logging vs error handling
Scott Tolinski
Yeah. And and also, just to be clear, logging is not just for Debugging, but also just for general information and understanding of what's going on. Right? So, yeah, you say how is this different than error handling? Because, basically, in regards to that same bit, how is this different than just errors and what's going on in your application? Sometimes it's it's it's a little bit also, At the same time, more targeted and less targeted because you can have less targeted info being logged, letting you know exactly what's it happening around what our potential errors, but just what's happening in general.
Scott Tolinski
But also you can have more targeted 2 situations where you think that there is going to be an error or could be an error to give you more context into what could be happening in that given instance.
Wes Bos
Yeah, yeah, like I just I just opened up my logs right now and I'm seeing people.
What to log in development vs production
Wes Bos
It's kind of interesting, you are seeing people go through the process of visiting the website, adding a course, buying the course, checking out, adding a coupon, getting the email being sent, then the email being the the link in the email being clicked, an account being created, somebody starting to view a specific video, And then progress on that video being and you can see all of that in your console as it goes through. And I specifically had an issue where people were going to I have magic links in my email, and people were going to magic links.
Wes Bos
And the idea of the magic link was always undefined. It it was the correct magic link, and immediately after, it was undefined. And I could not For the life of me, figure out what was triggering this undefined request. You know, like, it's not an error. It's it actually it was causing no issues to anybody, except There was an undefined request in my log, and I could not figure it out for the life of me. I finally finally trace it trace it down.
Wes Bos
You know what it was? What? It was an image tag to and the source of the image was undefined.
Wes Bos
And, it was trying to just, I guess when you you have an image tag, it tries to request the current URL as the source, and that was triggering because I had, Like a like a catch all path set up for the ID in the URL. It was it was catching that one as well and literally the the image pass. So I went into my template and I go, Oh, I had like a typo in my template and I fixed the image tag and whatnot, but that was driving me crazy. And it was only until I added Additional logging to see like, okay, like, is somebody being malicious here? Is this coming from the same user? Is it like a browser extension? Something like that. I had to add a whole bunch more log in. Then I was like, okay, I see what's happening here. And then I went to my template.
Scott Tolinski
It's it's funny, this just how much logs can both pollute and save your bacon sometimes. You know, sometimes if there's too much logging, too much noise, you can, you know, overdo much do certain things. But, you know, part of what Is good about having logging is that you can often go ahead and paw through the logs in a more structured and organized way. So, You know, too much information isn't necessarily a problem.
Scott Tolinski
So what should you log here? I'm gonna tell you what we log, and then we can maybe talk a little about what you should log. But, you know, I I think, personally, what I like to see in a log is I like to see, You know what type what, is I'm talking, like, server side logging here, specifically.
Scott Tolinski
Yeah. One one, like, really important thing about a log is the a time code in which this thing happened.
Importance of timestamps in logs
Scott Tolinski
Because without having the time in which something happened, going back and referencing it is kind of pointless. Right. You'd say at some point in some time, this this event happened. But if you knew when an event happened, specifically, maybe an error on your site or, some something happened. Right? And you want to investigate, so you're pawing into the logs, having that time code that says this happened at this time, Really important to be able to nail down exactly when when that happened.
Scott Tolinski
Yeah. You know, also, I I like what type of request it was, a get post put, whatever. I like the path that was requested.
Other useful log metadata
Scott Tolinski
I like the total time of the response.
Scott Tolinski
I like those types of things in in my logs. I also like to know what type of log this is. Is this an information log? Is it an error? Is it, and these can things these things can be color coded
Wes Bos
accordingly, so that an error log could have a red error or something. So that way, when you're looking at your logs, the errors stand out And the information ones kind of hide back or any of those types of things. Oh, that that's a good idea. I I so I'm half Excited to do this episode just so I can do a little bit of improving on mine because maybe we should talk about that specifically. Like, how do we log right now? So right now what I'm doing is I just have, like, different areas of the, application. So whether it is A magic URL, whether it's a log in, whether it's a progress update, whether it's somebody has invited somebody to their team account so they can Go in on it, whether somebody has changed their email, all that type of stuff. And I just basically have like an ID or a name for each one. Like I and I put it in square brackets, just magic.
Wes Bos
And then I put some information along in there. So things like URL, maybe query parameters, maybe body parameters. If it's a form, submit Other information about stuff that you specifically need. Unfortunately, at least I don't think you can't log the entire request a quest object because that would be absolutely massive and your your logs will get pretty large quickly.
Logging request data
Scott Tolinski
But I think I don't know. Do people do that? Do they log the entire request? I can't imagine. That seems like way too much text for everything that seems like that would never
Wes Bos
Work in a large context. Right? No. Because you would be like I certainly have had, like, log Files. We'll talk about what to do with these log files, but I've had log files get into the gigs and gigs. I once very early on, when I was just logging to log files on my server, I could not figure out why every couple of weeks the server would slow down until I rebooted it. And finally I realized this because it. I was using forever, and forever will put your logs in a log file. And then when you restart it, I think it deletes it or something like that. And I was running out of space on my server.
Wes Bos
Yeah. And it was just getting slower and slower because there's, like, not enough space to run things.
Wes Bos
And then when I cleared out the logs, they would go. And that's why you you have to have sort of a better approach for this type of stuff. Yeah. I've certainly gotten the email that says your Server space is limited,
Scott Tolinski
because you're running out of space and to only be like, wait. How is that possible? Oh, wait. Let me go check the law. Oh, boy. Yeah. Big old logs. And if you're it. Flocking every request that would, you know, we often forget as developers that, like, text is bytes, And you're saving a lot of text or a lot of information. Yeah. I mean, that's it's pretty easy to rack up actual a storage space of things with just text, just by writing a lot of text. Yeah, you get
Wes Bos
100,000 requests a day and
Scott Tolinski
You're logging a couple lines for every single person. Those add up pretty quickly. Yeah. Oh, okay. So one thing I also wanted to mention that I do, just for fun for our Information logging, especially in our request. I I do a little emoji based on how, like, long or short The total response time was. So I start counting when the request comes in, and then I stop counting when the response is going out Just via middleware, and I measure that time. And if that time is really fast, you get a rocket ship. If it's Shorter, you get a a bunny rabbit. And if it's really long, then you get a turtle. I've been I've been thinking about expanding this a little bit more, but It's really simple just to see a turtle, a rabbit, or rocket ship in your logs. It makes it, like, for me, just really visual in terms of alright. It. I'm working on this one component, and I've been seeing a ton of turtles in development.
Scott Tolinski
Why am I seeing so many turtles in this specific route, but not other routes.
Wes Bos
That's awesome. What else should you log? Descriptive messages about what happened.
Logging descriptive messages
Wes Bos
So not just Login attempted, but login attempted with user email address. Obviously, don't put passwords in In your logging and maybe we should talk about that really quickly is logging personally identifiable information.
Wes Bos
You certainly start Get to step into areas of GDPR and all these rules around private information and tracking or whatnot. So you certainly make sure you are up to date With all of that, as well as scrubbing the logs as part of when somebody does request to be deleted from you, you have to think about, Oh, like, of course, you have their user and purchases and things like that, but they probably also have information about
Avoiding logging personal data
Scott Tolinski
maybe you have that in a log somewhere that also should be scrubbed. Yeah. I mean, it's important to know that it could just become another attack vector.
Scott Tolinski
So if you do have something, that is Secure needs to be secure in your log and someone get axe gets access to your logs, then that's as bad as, You know, them getting access to the information itself.
Wes Bos
Yeah. Yeah. That information is sitting there. Or even like other employees that shouldn't necessarily have access to that information. You put all this work into permissions. You have to be careful that you're not putting anything in the logs that other employees could have access to. Yeah. Especially if it's insulting to those other employees. Yeah. So we'll talk about like what about like development, staging, production? A lot of people I don't Specifically do this. I really only just log stuff that I I think I might need, but, you can set different levels of logging. It goes From, like, error warning all the way up to verbose and silly where you you literally log absolutely everything.
Log levels from error to verbose
Wes Bos
And that could be actually really helpful, specifically, like I know with ESLint.
Wes Bos
ESLint has like a a silly mode or a verbose mode where it will log every single thing that it's doing, and that could be helpful to follow the request along. Like at a certain point, that's also what, breakpoints are 4 in your code base, but it can be nice to nice to see what it is doing. Yeah. I mean, there are times when you just just dump them in to try,
Scott Tolinski
to get it to get it, some visibility into what's going on, especially in development.
Scott Tolinski
But in production, you know, Yeah. I I pretty much keep most of my, normal, like, informational logging in production.
Production vs development logging
Scott Tolinski
Like, it's really helpful to be able to see. Alright. A get request came in. You know, this this is just at a glance, like, is what's going on in the site, but also At a glance, even though I do use tools to evaluate my speed of the site Mhmm. It's really nice to see at a glance in the locks, The, emoji that I put in there just for fun. And these are only server side, so it's not like these are, you know, polluting the client side logging experience or anything like that, which honestly, you You know, your site probably shouldn't be outputting too many things to the the client in production unless you're, you know, Trying to have fun with it, but you gotta kinda remove some of that stuff. I leave probably more than I should in
Wes Bos
on mine because Sometimes I get emails from people and they'll they'll show me their console. And I was like, well, kind of glad I stuck that in there. But on the same breath, This is not part of the sponsor, but one thing that I really like is if you do have an error in that goes into your century or whatever, Century has this thing called breadcrumbs, which will it will show you, like, which functions were called up to the error, but anything that you console log will also Be included in the breadcrumbs, and that I found is very helpful because you can see. And then I like, when I was having an issue with a specific thing The other day I went in and added more logging, and then I could go to the breadcrumbs. Okay. Okay. Now I have a little bit more insight into To what is happening. So that was super handy too. Yeah. We often talk about the name of the game being visibility
Logging security events
Scott Tolinski
and debugging, right, knowing what you're trying to fix. Yeah. And that's just really where logging comes into play here. I think one thing I really love seeing come into my logs is that somebody tried to access WP admin and got a failure.
Wes Bos
Yeah. That's the other thing is, like, bot logs as well.
Wes Bos
So bots will try to hit Common endpoints, bots will try to submit forms with with random data. I had a bot the other day try to submit, a bunch of, like, PostgreSQL injections into a form.
Wes Bos
And it's hilarious. I I don't use Postgres literally anywhere, so that wouldn't have worked. But it's not somebody sitting there trying to do it.
Logging bot access attempts
Wes Bos
It's a bot trying. I don't know. I think it was something like It went on for about 6 or 7 hours until I until I jumped in and go, oh, like this form should probably have a have a CAPTCHA on it so that the bot can't do that.
Wes Bos
But it was kinda funny watching the request come in every 2 seconds with the the the new piece of information that they were sent in. And They don't do it. They do it just enough that it doesn't hit any, like throttling. Yeah. Rate limiting. That's so that's another thing you should be logging is any throttling or rate limiting that happens in the app level. You Modeling a rate limiting that happens in the app level.
Logging rate limiting
Wes Bos
You can log that to show, but the bots are smart enough to figure out what is the limit For this website, and even if it takes 6 days to get all of the possible combos through, they can do that. Yeah. I actually
Scott Tolinski
it's funny. I was just writing something the other day to do, like, automating browser tasks, and I had a little set time out in a loop Because I knew that if I didn't Yeah. Then it would get hit by the rate limiting. So I was just like, alright. If I set this set time out loop to be 200 milliseconds, Alright. It fails after the first one. I set it to 300, fails. 400, succeeds. Alright. 400 is my number. It's
Wes Bos
So you could, like, dial in exactly what the rate limiting is. Let's talk about where to put logs. So at the very basic, Either your service will handle the logs for you. They'll stream them in, and you can just go to logs in the dashboard. Or if you're just on, like, a, like a like a straight up v p or VPS server, Linode DigitalOcean, something like that will generally have log files in there that you can, you could go in and download and whatnot. Generally, these log files are massive, massive, so they they can't. You can. And like Back in the day, it used to be hard to just open them up in your text editor.
Wes Bos
Text editors are very good at opening up files that are 2 gigs And searching through them now. So it's not so much of an issue.
Log storage and retention
Wes Bos
But most services that do hosting will allow you to do what's called log drains, meaning that, okay, we'll keep logs for we'll keep the last 10,000 logs or we'll keep the last week worth of logs.
Wes Bos
And then after that, they're deleted, because at some point you should you shouldn't keep logs around for for that much longer.
Wes Bos
But if you do need to keep them for a little bit longer, then you have to port them into something else. So whether that is as simple as a text file on AWS or there's lots of services out there that are specific log drains, and they are really helpful because you can do things like Search for specific words. You get syntax highlighting. You can filter sorting filters or all that type of stuff graphs and all. Yeah. Yeah, I don't do any of this because sometimes I look at the the prices of these things. I'm like, I don't need another $20 a month for something like this, you know, but I I look at it, like, specifically this one better stack.
Wes Bos
Log tail
Third party logging services
Scott Tolinski
looks nice. Yeah. Log tails great. You know, I've used I've used Logtail. I've used Paper trail, those are 2 of the big ones. Some of the other ones are Sumo Logic, LogDNA, Logs dot I o, Sematext logs. Datadog has logging. LogicMonitor has logging. Dynatrace has like, there's a lot. Right? Yeah. This is like a big a big thing where some of these do more than just logging. Right? But, you know, we're talking The the big boys for just straight up logging, Log Tail and Paper Trailer are probably the 2 biggest ones. I've used both of them. Both of them, you know, they were great to have, especially as diagnostic tools. When you were looking for, like, a specific instance that happened, I found it to be way easier to find a specific instances or specific issues or really dive into the logs a little bit more with these tools. But at the end of the day, like you said, they're they're Just kind of unneeded expenses for our level of what we what we're working with. You know? I I can dive into the log files no Problem and still get access to the same information, so I probably shouldn't be paying a service just to be, making it a little bit easier. But if I was on a big project with a big team with more requests than what I'm dealing with right now. I think something like this would be essential.
Wes Bos
I just I yeah. I I don't need it for our size. So when you actually go ahead and log, I said earlier I'm simply just using straight up console log. But there are lots of other packages that will do these for you.
Wes Bos
Winston is the big one that's usually included in Express apps and Node. Js space.
Using logging libraries like Winston
Wes Bos
They allow you Do different types of logs and pass context to it and all kinds of good stuff like that. I've never liked that because I like the idea of that, but I hate having to import A package in every file, which it's I think maybe less of an issue now with the auto import in Versus Code. So maybe I should take another look. Do you use a specific package? I always used Pinot before p I n o from, you know, the awesome Matteo Colina.
Scott Tolinski
And this was the one I used because it came with Fastify and Mercurius, and I really like it. There's it's a really It's really robust. It does a lot for you.
Scott Tolinski
Low overhead. It's, overall, a super nice logging package. But, You know, I would probably instead of trying to use this in a sense where you're dropping it in like a console log, It's something like this, like a service I would probably try to, like, intercept intercept errors or intercept requests and do this in more of, like, a middleware type of way and then just use straight up console log for everything else, I guess. Oh, yeah. Yeah,
Custom middleware for logging
Wes Bos
that makes sense. We should do a show on middleware. I I don't think we've ever done that. Yeah. I just wrote a little middleware that I I think I had been using,
Scott Tolinski
in SvelteKit to automatically parse Form data from our forms and make them just available in in SvelteKit form action. I saw that. You you published it. Yeah. I published it. It's like I've had this thing in my code base for a little while. I actually have a few of those. Like, I have a SvelteKit logging one, and I have her off. It's like, hey. It should take me cup couple minutes to put this up live somewhere. So Yeah. Yeah. I Specifically, the the one thing that has got me with the middleware I I use tons of middleware, but I never like, I wish that the TypeScript types would update
Wes Bos
For requests that are after the middleware, you know, like before the middleware, you know that it's not going to be there. And after the middleware, like, Wherever they are, they you always have to do like an if statement to check if it's specifically there, which is probably better type practice. But it would be nice if somehow you could You would know if the middleware was run before it. And it's kind of hard because you don't know the functions where they are, you know? Yeah, totally. But but we'll we'll throw that on the books. Middleware ones coming up. What else do we have here about logs? I think that might be it. Yeah, I think that's it. It's helpful to log Log stuff that you think you need. Put them in because sometimes you're going to need that information after And you realize, oh, shoot. I probably should have had better logging in place. So take a take a couple of minutes and maybe add some better logging to your app. Yeah. Absolutely.
Wes Bos
Alright. Thanks for tuning in. Catch you on Wednesday.
Wes Bos
Peace.
Scott Tolinski
Head on over to syntax.fm for a full archive of all of our shows.
Scott Tolinski
And don't forget to subscribe in your podcast player or drop a review if you like this show.