578

February 20th, 2023 × #logging#debugging#visibility

Logging

Wes and Scott discuss the value of comprehensive logging in web development and some best practices.

or
Topic 0 00:00

Transcript

Scott Tolinski

CSD.

Scott Tolinski

Welcome to Syntax.

Topic 1 00:30

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.

Topic 2 01:48

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.

Topic 3 02:33

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.

Topic 4 03:53

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.

Topic 5 04:36

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.

Topic 6 05:56

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.

Topic 7 08:43

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.

Topic 8 09:16

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.

Topic 9 10:32

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.

Topic 10 13:30

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

Topic 11 13:52

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.

Topic 12 15:21

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.

Topic 13 16:05

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

Topic 14 17:38

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.

Topic 15 18:18

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.

Topic 16 18:52

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.

Topic 17 20:16

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

Topic 18 21:18

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.

Topic 19 22:54

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,

Topic 20 24:05

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.

Share

Play / pause the audio
Minimize / expand the player
Mute / unmute the audio
Seek backward 30 seconds
Seek forward 30 seconds
Increase playback rate
Decrease playback rate
Show / hide this window