RESTful and HTTP APIs in Pyramid Transcripts
Chapter: Logging and monitoring
Lecture: Using logbook
Login or
purchase this course
to watch this video and the rest of the course contents.
0:02
Now that we have logbook all set up and working, let's actually switch back to dev, now let's go ahead and do a little bit of logging.
0:09
So let's begin by logging this startup action, so a lot of this sort of system set up a configuration
0:16
is really stuff you want to register in the system start up log, so for example the core settings maybe you want to save that,
0:24
you very likely want to save the database connection information like this is the database we're using right now, so we can go back and check that out,
0:33
possibly stuff about the renderers, and the routes maybe, maybe not, but definitely the db seems like something you'd want;
0:39
so let's go over here, and let's actually work with logbook. So, we'll come over here we'll create, I'll just call it a log, so we'll say logbook,
0:46
it's not imported, this file, until now and we would create a thing called the logger, and these loggers get names,
0:54
so the name is part of a hierarchical type of output that it gives here, so you'll see that it gives you the time
1:01
and the level and the location within the app so I am going to call this app start up, something like that,
1:06
or we maybe make it very obvious, make it all caps, I don't know take your pick. So then let's go ahead and make sure we turn the log
1:13
and we will use that above, so we can say log. now we have things like notice or warn or error or trace, so let's say
1:22
that this is a info, maybe something like that, e'ill send out this info message and it will say something about the log file and the mode
1:33
so configured something like that, ok, so configured logbook in so here we'll say dev mode, if not log file else prod mode, something like that,
1:49
and then the next thing we want to pass is the log file, right, so for now let's just go and let's just run it
1:56
and see this message come out, so run it again, we're running in dev which means the message goes to the output stream,
2:01
and here's what one of these messages looks like, configuring logging with, go in here and get rid of that print message,
2:10
ok so here we got this exact time of the recording, pacific standard daylight time I guess, and we have an info level message
2:19
from this part of our application, here is the message so we've configured logbook in dev mode with no file,
2:24
now let's go a and switch it to production, try it again, okay, it's running great, where is the message, message is down here.
2:33
So I think I got to refresh this, here we go, so now notice that this message has gone directly exactly the same message
2:43
saying some time gone to this file here, and notice that the year month day is in here
2:50
and of course it's going to rotate around as the days change, right, tomorrow will be the thirteenth, so 5-13, things like this.
2:57
Now we could have a go both to here and to here but you'll see that when we get to deployment things like the μwsgi log catch standard out
3:07
and put that in there already so you would basically be duplicating this log message stuff to theμ wsgi bits
3:12
and you know, you can decide whether you want that but I don't think it works out really well. So we're going to go like this, let's go back to dev
3:20
let's go ahead and do a little bit more work so we got our logging here, we'll call this log we could make this
3:25
like a global variable here but let's go into like this, we'll pass it along there, pass it along here,
3:31
and now what we can do is we can say something like this, I think we're doing the logging in there right, nope, okay good, so let's do our log here
3:45
at one point we're printing that out, and let's say that this is an informational thing and based on the way we set things up that means
3:51
this is going to show up in production, whereas maybe more chatty stuff a lot of the success type things you probably don't want to log
3:59
so well say configured db with sqlite file like this, and we give it db file, okay, so if we run this again,
4:11
now we'll see a logbook is configured with no file this one is just really just to show you guys, I'm not sure I'd really log that
4:18
but this one definitely configure db light with this file or connection string or something like that that's totally reasonable, all right,
4:26
maybe down here we're also going to do log, and do something like this log.info configuring your image for cors permissions, and spelling is hard,
4:46
but the tools are here to help, okay, so we run it again, ok, so we are getting our message here
4:53
now we could have actually gone in here and say you know what, log.trace adding cors permission to request
5:02
and go down here and do a format request.url, that would be underscore, let's fix that for a moment,
5:11
now if we come over here and we make a request of this, and do a few of them, click here, must be authorized, sure,
5:18
so notice, you can see all of this stuff adding cors permission trace, trace, trace, trace,
5:24
so, this is very very chatty, you don't want to normally log this but maybe you're trying to debug it, so we could have this trace,
5:33
I'd still find even things this chatty like maybe I'll put that message there, but then, actually not keep it around most of the time,
5:41
just if I'm like wait, what's up with cors, I thought that was working put that back, right, but you can see we have these different levels,
5:46
we have informational, we have trace, and we have the app start up let's add one more area where we might do some logging.
5:52
So a couple of things to note before we leave this page, so once we've done this global init, throughout the rest of our application
5:59
we can now just say logbook.logger and allocate one of those, give it a name and use it and it will pick up the settings done in global init,
6:07
so you really want to try to do this init logging like as soon as possible, right at the beginning of your app. So even these other start up operations
6:16
can have logging configured and ready for use. Okay so this is great, let's go over to our auto api here
6:21
and do one more thing, let's go and import the logbook as well and let's create a logger here, so we'll say log equals, call this auto api,
6:35
now if you want to look at, let's go back to the messages really quick, if we were to look at these messages as kind of a hierarchy here right,
6:42
so we've got the level and then we've got this thing and we've got the message, we could do it like this api/auto
6:50
and then maybe we'd have other things like accounts or whatever, and this might indicate like these are all part of the api,
6:57
but this part is the accounts, I don't know, it's up to you; let's go with this, I think there's probably some some utility in having it that way
7:04
if we want to go back and parse the log files. Alright, so now throughout this, here we have a print message, right,
7:10
any time you see a print message that should probably be going away, right so it's going to be a log and notice this is kind of informational,
7:17
this is just hey, things going as usual, we're listing the car, maybe this would be a trace, or maybe an info, I'm going to go with trace on this one.
7:26
Down here, similarly let's grab the same thing, this is going to be car details for cars such and such and user such and such,
7:40
maybe this needs to be car id, like so, ok so let's go ahead and just see that these are working;
7:49
notice, here's our startup messages and info info info app start up,
7:53
and if I try to click on this, we're not going to get the message about seeing the cars,
7:57
maybe we want to have a permission failed type of thing, right, maybe over here in our auth, we are going to have a section
8:03
where we deny people access to it, we might want to log that. So that's up to you, we could do it, we'll just probably finish out this one over here,
8:12
so when we get a single car this makes a lot of sense, now here's where it gets interesting, so we could say something like this
8:20
log.notice info, how about info, this is sort of a preliminary successful thing like hey somebody is trying to update the cars
8:27
we'll say we let me grab the user name here so we'll say the user such and such is creating a car, like this,
8:35
so here's an info message, but when there's a problem maybe we could say something like log.warn, so this is not a problem with our system,
8:44
but this is a problem with the message sent in by this user. The submitted json body couldn't be parsed for this person here, ok.
8:56
So that's pretty decent, if there's some kind of problem we're going to give you a warning which maybe maybe this is even a trace, I'm not sure,
9:05
but people modifying data, you probably want to log that but you can decide trace, not trace, whatever,
9:11
but certainly you want to log like mistakes and errors, right, so down here, you could say submitted invalid car, we can say reasons you're here
9:22
now we probably want to be a little bit careful with this, because this error message might have new lines and stuff that might mess up our logs,
9:33
so let's be careful how we put this in here, so we go here and I would like to just comma separate this or semicolon separate it
9:41
and we'll do that with a quick join like this, okay so let's go and do that, and finally maybe this one is a proper error, right
9:50
this is our problem, not their problem failed to save car, and at this point, maybe we're just like you know what,
9:58
we are just logging everything, like this, so just straight up log the exception, in fact we're returning it back which made me not be advisable,
10:06
but we're doing it there, ok so let's run this and get to where we can actually call this with postman, with authentication, api key and all that
10:15
so here's our get autos, and we have you can see our authorization key we're doing json, that's cool, so we send that over,
10:23
trace api listings, listing the cars for jeff, remember that's the api key for jeff that we've been using.
10:31
Let's go over here and make another one, and this time let me grab one of these so I remember the format
10:38
and let's say we're going to do a post to create a car so go set the body to this, we can't have an id
10:48
this is going to be a very fast new Opel with lots of extras this will be, let's just call it slightly old Opel, not so many extras ;
10:58
now let's make that json malformed right, and the url is going to be the same that's our model here and I run this, how's it going to work
11:08
it's good and say permission denied, right come down here you must specify authorization header, so we'll do that,
11:15
and then it should come up with an error, so we have headers authorization with that value,
11:22
send it again, boom could not parse json, invalid character here
11:26
okay that's fine, but let's look in the log files, info the user jeff is creating the car
11:31
ooh, warning they submitted a json body that couldn't be parsed now we could print out the json body if we really wanted to,
11:37
like I said that might mess up our log files, we might need to encode it in some way
11:41
so it is like escaped in the log files who knows; but this at least lets us see like hey there's something going wrong in our api auto section,
11:51
now finally, let's go over here and make a few more obvious mistakes so let's have some negative prices, and let's get rid of last seen,
12:03
that should generate a number of errors, it does, there is two here pricing and year and we look down here now we can see warning submitted
12:10
invalid car price must be non negative, year must be non negative. Okay, so this is nice it's showing up in our log and so on.
12:17
So I guess we need probably one more message to make this all work, so right here when things are all good let's say this log.info
12:25
and where is my user bit, so and so has successfully created car with some id so here we'll pass in the name, we'll pass in the car and the id of that
12:39
remember this comes back from the database, so one more time let's go and actually create a valid car here
12:45
still, we have these problems, let's go back to our body here, and say that's positive, that's positive, put our last seen back
12:55
try again this should work, error 500, ok that's not great could not save car parser must be a string or character stream not a datetime.
13:04
I think that actually might be a real problem we have in here let's go check here, yes I think that the car once we've upgraded it
13:11
has already converted that to a datetime so it actually had a problem but check this out, we really did save a full on crash in our server,
13:19
all right so I think we'll be good now, let's try it one more time send it, 201 created awesome, here you can see the car came back
13:25
with this id that ends in 5b, let's go see what we got— excellent, we have an info in the auto api
13:32
jeff has successfully created this car such and such, all right so I think we've really driven home this idea
13:38
of working with logbook and adding the logging. Now one thing that always bothers me about having tons of logging,
13:44
is this used to be very very clean and easy to read and now it's just got you know, just more stuff okay, so I don't really know how to solve that,
13:54
there's not a lot I can do to move that stuff out because every single line is kind of its own unique message and data and whatnot,
14:02
so I think that's just a fact with having lots of logging, but it does make it a little less nice here,
14:07
however, when we're running, and we can come down here in dev mode or we can actually just tail our logs or whatever,
14:15
then you can actually see what's happening in your app and that's really gratifying that you are able to go back and track that down and so on.
14:22
So logbook very nice we have the different levels, we have the different outputs, we have the different locations, the error formatting and so on,
14:30
there's email, there's sms, there's lots of cool stuff with logbook,
14:34
so definitely consider adding this to your api before you send it off to production.