Logging in FastAPI Apps / Writing a FastAPI Middleware

in this video we're going to learn how to set up logging with the fast API framework in Python and we're going to see how to set up middleware in order to log out details of every single request and response that comes into your application and we'll also see how to ship those logs to better Stacks platform in order to analyze and search the logs and find important events that are occurring in our application let's get started now let's start by creating a python virtual environment and installing fast API into that environment I have the documentation open at the moment and we'll leave a link to this below the video what we're going to do is go to the install fast API section and we're going to run this command here pip install fast API all now I'm going to cross over to VSS code where I have a directory with a main.py file that's all that's in that folder and what we're going to do to start with on the terminal is create a python virtual environment using the venv module so python DM Ven and let's give this environment a name of Ven fast API I once we've run that command you need to activate the virtual environment I'm on windows at the moment so what I'm going to do is activate it with this command and you can see that that is activated now if you're on a Unix system you can use the source command in order to do that what we can then do is install fast API and actually I'm going to just paste that command that I copied from the documentation and that's going to install fast API as well as other dependencies such as uicorn and uicorn is the async ready web server that we're going to use to serve the fast API application once that's done what we can do is we can actually create a small fast API application and we'll build some logging into that application including building a middleware slightly later in the video so to start with let's import from Fast API the fast API object and in order to create a fast API application the most simple thing you can do is instantiate that and store it in a variable which we will call app and then using this app object we can Define handlers and endpoints in the fast API application so I'm going to Define an endpoint that takes a get request and the path for that is just going to be a slash so it's the base path in the application and then what we can do is we can define an async python function and this is the Handler for the root so let's call this function index and then we can return a bit of content and in my case I'm going to return a dictionary here and we'll give it a message of hello so a very simple endpoint here it returns a python dictionary containing a key message and we can type in that return type if we want using this syntax here until the fast API function that this is going to return a dictionary and fast API will then convert that to Json now what I'm going to do is replicate this endpoint we're going to create one more endpoint and this one is going to be to a URL that we're going to give a path of upload videos and I'm also going to name the function upload videos and we can change the message here to video uploading and later on in the video we're going to introduce a bit of latency for this function to simulate a long running request that you might get for example when you upload load a video so now we have two handlers let's import uicorn at the top and remember I said that was the web server that we're going to use and at the bottom we're going to run the web server here we're going to check if we're running this file as a python command and then we're going to call the uicorn Do Run function if that's the case and we pass our app object into that function as well as some details here for the host and the port and you can change those if you need to now what I'm going to do in order to run this is make the terminal a little bit bigger here and we're going to run the uicorn main app command and I'm going to pass the D- reload flag to this so that the server will reload when any changes are made to the code so we now have a server running on Local Host 8000 if you go to the browser you can see that at the main endpoint here we get the response of message hello and we can add the other endpoint here of upload D videos and we're going to get back that different message for the second Endo so we have a fast API application albeit very basic but how do we add logging to this application let's go back to VSS code and we're going to create a new file in the project that's going to be called logger dopy and we're going to Define some utilities from Python's logging module in this particular file so at the top I'm going to bring a couple of imports in we're going to import the logging module and also the CIS module from Python and then what we're going to do below that is get the root logger so I'm going to get that logger by calling a function in the logging module and that's going to give us back an instance of a logger in Python so what we're going to call is logging doget logger and this function can optionally take a name it can be a string or none and that's going to return a logger with the specified name and create it if necessary and if you don't specify a name as it says here it's going to return the root logger so this line of code is going to give us back a logger instance in Python what we're going to do after that is we're going to create what's called a format and a formatter in the python logging package is going to determine the output format of your log records so let's create a variable here called formatter and that's going to be equal to an instance of a logging do formatter object now this takes some arguments the most important one is the format so let's pass in a format string here and we're going to set that equal to a string that will determine the output format of our logs now what I'm going to do is go back to the documentation for the logging package in Python and what we're going to look at is on the left hand side here it's the log record attributes so a log record basically repres presents a piece of log output and this log output can have some attributes that are predefined in the logging module so if we scroll down here you can see some of these attributes that we can reference in our log format for example this one here is for a human readable time when the log record was created and we also have other ones such as the level name and level number and the level name in the logging package refers to the debug info warning error or critical log level and each of these have a corresponding number that determines the severity and the higher the number the more severe the log event is and we'll leave a link to this below the video there are many of these log attributes but what we're going to also reference is the message and that's the output message that's passed into the log level method so let's go back to vs code and we're going to create a log format here so the first thing we're going to Output is the time at which the log record was created and then we're going to put a space and a Dash and actually I'm going to move this to a new line so we can see the entire line better and after the dash we're going to put the level name which could be info or error or any other log level that's defined in your application and then I'm just going to put another Dash here and we're going to Output the message that's the actual message passed into the log method as we're going to see very soon so this is a very simple format for our log records what we're now going to do is create some handlers that are going to determine where the log records are going to be shipped to so let's create a couple of these the first one's going to be called stream Handler and that's going to be a loging do stream Handler and and this can take any stream as a parameter but if you don't specify one it's going to send the output to standard error so just to demonstrate this I'm going to pass in standard out using the cy. standardout property and that's going to send the log for the stream Handler to standard output now we can Define another Handler here which I'm going to call file Handler and that's going to be a loging do file Handler instance and the main argument we need to provide here is a file name so let's provide a file name of app. log once we've done that we can set the formatter so basically we're going to take each of the handlers like the stream Handler and we're going to call a method on that called set formatter and we can pass in the formatter object that we created on line 8 and I'm going to do that for both of these handlers so we're also going to do it for the file Handler and we're nearly done what we need to do now is we need to add the handlers to the logger instance so we have the logger that we created at the top here using the get logger function what we're going to do is we're going to set the Handler's property on the logger and we're going to set that to a list of all of the handlers that we want to use in this application so I'm going to use the stream Handler and also the file Handler and the Handler's property is telling the logger where to send the output records so it's going to send them to standard output and also to the file that we specified for this file Handler and the final thing I want to do is set the log level we can do that on the logger by calling it set level method and the level that we want to set is logging doino so we now have the configuration for this logger and we've set some format Ms and handlers on the logger what we can do now is go back to main.py and at the top here what I'm going to do is import from logger the logger object that we created in that package and we can use that logger just below the application so for example I can call logger doino and we can then pass a message into that the message I'm going to pass is starting API now what we can do is make the terminal a bit bigger at the bottom and if I save this file it's going to reload the application and it says starting API that was the message we passed in and it's got the format that we specified we've got the time at which the log record was created then we have the log level and then we have the message so we now have a logger that we can use in the fast API application and we can also add log statements to our Handler functions in fast API so let's go to the index function and I'm going to put a very simple log message in here and again we're going to call the logger doino function and the message I'm going to pass is simple it's just request to the index page and we can add a very similar message to the upload videos page for now request to the video upload page now we'll add some slightly more interesting code in a second but let's test this out if we go back to the browser here and go to our upload videos endpoint if I refresh this page and go back to the terminal on vs code you can see we get this output log here containing the time the log level and also that particular message that we passed into the function so we have some very basic logging going on here we've got a module in our application called loger dopy where we Define the basic setup and then we have have in the main.py the ability to import that logger and use that logger so we use it here and we also use it in our Handler functions as well now soon we're going to add a middleware to log output for every request but what we're going to do before that is we're going to add a Handler that allows us to ship our logs to better stack and this is vital for centralizing your logs across different services in a single place where you can then search through them and build some analytics around those logs and also helps with identifying events or anomaly that are occurring in your application so what we're going to do now is go to the better stack log page and we're going to create a source that allows us to take the logs from a particular service so let's connect our source now and we're going to give it a name here and let's give it a name of fast API demo and we're going to select a platform and we can search through the list available here and we're going to select python so let's create that source and then we're going to get back a token as you can see here let's copy that token and what I'm going to do is go to logger dopy and right at the top of the this module I'm going to add the token here so let's create a variable called token and we're going to set that equal to the string that we get back now in a real application you should extract that token to the environment and then read that in securely and of course that should not be put on GitHub or any other source control system but we're just going to leave this here for demonstration purposes in this video but make sure you don't hardcode these types of tokens in your applications so what we have now is a source and we can now ship our logs to this source using the token that we've been given and in order to to do that we need to bring a new package from better stack into our application so I'm going to go to the better stack documentation for logging in a python application there'll be a link to this just below the video what we're going to do to start with is copy the PIP install command and we're going to install the log toil python package and this is basically a package that allows you to ship your logs to better stack so let's copy that command and go back to VSS code I'm going to stop the fast API server and we're going to paste that command in and install the log tail python package once once we've got that installed we can then use that package in our application I'm going to go back to the documentation and you can find the instructions on how to use this with a python app in this documentation so what we're going to do is import the log tail Handler so this package gives us the log tail Handler that we can use to ship logs to better stack so let's import that at the top and we're then going to take the log tail Handler and we're going to go to the section that we have here where we created two handlers and we're going to create another one just below this and this is going to be called the better stack Handler now we're going to set that equal to an instance of the log tail Handler and what we need to pass in here is a source token and we need to set that equal to the Token that we got from the better stack user interface when we created that source and of course we saved that token at the top of this file on line five so we're going to reference that token here in the argument and once we've created this better stack Handler what we can then do is go down to the logger do handlers line and we're going to add our new better stack Handler to that list so now we have three handlers in the application and of course you can add and remove these as you wish you don't need to use all of them if you don't need to log to a file you can just remove that Handler but I'm just going to keep logging to all three of these and what I didn't show earlier on was actually the app. log file you can see the logs that are being collected in this app. log file and this corresponds to the file Handler that we defined here where we told the file Handler we're going to send those logs to the app. log file so we have that on the left hand side our logs are going to standard output they're going to the file and now hopefully they're going to go to our better stack Source via this log tail Handler so let's run the application again on the terminal and once that's running what we're going to do is go back to this page here for upload videos and we're going to refresh the page and we can do the same at the other end point where we just get back the message of hello if we go back to the better stack platform here and we go to the live tail for the logs we should now see that we are actually getting getting these logs coming back to the better stack platform and we can click these logs to get more information about them so for example we get the fil name that emitted that log we get the message and these contain very basic messages at the moment and we also get some information about the level and severity as well now you can add your own key value pairs to the python log output and we're going to see an example of that very soon what we're going to do now is we're going to create a middleware in our fast API application that's going to log details of every request that's coming into the application now let's start by going to the fast API middleware page so a middleware is a function that works with every request before it's processed by a specific path operation which is basically a Handler function and this function also can process every response before it returns it to the client and the benefit of that if we go back to vs code and look at the code that we have in main.py if we look at the two Handler functions we have two outputs here to logger doino now imagine that contained the same data and we had it in 50 different endpoints we might want to consolidate that and instead of adding log calls in every single Handler if we have a common functionality there we can extract that to a middleware that's going to run before every request so how do you define a middleware in a fast API application let's go back to the middleware page and as we've seen we have an app object when we instantiate fast API we can also use another decorator here the app. middle we decorator so I'm going to copy that decorator and we're going to go back to main. Pi and I'm going to Define this middleware just above the handlers and later on we're going to extract that middleware to its own file so we use The app. middleware Decorator and then I'm going to Define another async function and let's call this one log middleware now a middleware in fast API it can take two arguments first of all the request object that is passed in as the first argument and then we have a function passed in as the second argument called call next so let me just copy these and we're going to bring them into the code here and we need to import the request object from Fast API so let's do that at the top now what I'm going to do within the middle wear function is I'm going to create a python dictionary that we're going to call log dictionary and that's going to be equal to a dictionary with two keys and the first key that we want to add is for the URL we can get the URL for this request by using the request. URL property that gives us back a URL object that contains another property called path and that will give us the full path for that request and we can also add a second property to the dictionary and that's going to be the request. method and that's going to tell us what kind of method that was sent to the back end was it a get request a post request or so on so our middleware now has a dictionary containing a URL and a method what we can do is we can call logger doino here and I'm going to pass the log dictionary through to that and what that's going to do is it's going to Output that log dictionary as the message for this logger info call and because we're using this as a middleware this is going to be run on every single request that comes into the fast API application now we need to then progress the middleware onto the next middleware in the chain or to the actual Handler function if it's the last middleware so what we're going to do in order to do that is we're going to create a variable called response and we're going to call this function here that was passed in as a second argument it was called call next we can call that and pass the request into that now because we're in an async function here we can await that function returning and what this is going to do is it's going to return the actual response that's to be sent to the client and at this stage we can modify that response for example we could add an HTTP header that we want to send back but all we want to do is just log out this data so what I'm going to do for now is just return the response to the client so this is a middleware that does some operations on the request coming into the client and it logs out some data and then it simply Returns the response we're going to see later later on that we're going to add another property to this log dictionary that can only be calculated when we've generated the response for the client so we are going to modify the code in between generating that response and returning it a bit later in the video so let's now test this out I'm going to remove these log calls that we have in the function we don't need those anymore and we're just going to see the log output for this middleware here so let's save the file and go back to our page here I'm going to refresh this page and we get back the same response but what we need to know is has the middle wear run in the application so let's go back to better stack and you can see this log record at the bottom here if I expand that you can see we get back the message containing those two properties that we added to the dictionary so the URL which is just slash and the method which in this case is get and we can test that for the other endpoint so slash upload videos if we do that and go back to the live tail this time at the bottom you can see we get back the message here containing a different URL it's still a get request but the UR URL has changed to/ upload videos so the log output generated by the middleware is now being sent to better stack what we're going to do now is show how to consolidate the middleware in its own module so what I'm going to do is cut this out of main.py and we're going to create a new file here called middleware dop and I'm going to paste the function in here and then we're going to remove The Decorator because we haven't imported the app and we can't do that which we'll show in a second because it will result in a circular depend y now I need a couple of imports at the top here we need the request object from Fast API which we're using as a type hint and we also need the logger object from the logging module which we're also using in order to call methods like logger doino so we now have an async function called log middleware and it lives in its own module the middleware dop module so now that we've defined this module let's go back to main. Pi and we don't need to import the request object and we need to now add this middleware to our app that we have here on line five and we're not using that decorator anymore how do we register the middleware well it turns out the app object has a function called add middleware so we can use that function but the problem that we have here is that that expects a middleware class and what we have in middleware DOP is a function called log middleware so let's go back to main.py and to start with let's import from middleware that function that we defined called log middleware and now we need to add it to the app object but as I said it needs a class so what I'm going to do is go to this documentation or rather this issue that was raised on the fast API GitHub page and the issue question here is how can you get access to the app object in a different file from main.py now if we scroll down we can get the answer to this and this answer is very relevant to us it's about adding a middleware that's defined in another module of the application what we can do is we can use the base HTTP middleware class from starlet. middleware so let's bring that Import in at the top here we're going to go back to main. p and just underneath our middleware import let's import the base HTTP middleware now fast API basically runs on top of a framework called Starlet and this is an async framework for developing web applications and this base HTTP middleware we can go to the documentation for that so let's cross over to the Starlet documentation and what you need to do in order to implement a middle wear class that uses this as its Base Class is you must override the function called dispatch and you can see that in the signal below we have a class that inherits from the base HTTP middleware and it defines a function called dispatch and then within the dispatch function it defines the code for the actual middleware now what we're going to do is we're going to follow the guide on this GitHub issue we're going to pass the base HTTP middleware into the app. adds middleware function and then we can pass a dispatch method and what we're going to do is we're going to set it equal to that method that we defined in the middleware dop file and that's the log middleware method so let's go back to main.py and to the add middleware call on the app we're going to pass the base HTTP middleware from Starlet and then we're going to pass a dispatch function that's equal to log middleware and at the bottom we're getting this error that we cannot import base HTTP middleware now we can go back to Starlet here and see what's wrong I've copied that import from this issue on GitHub that was raised in 2019 I believe the module has changed that is now starlet. middleware dobas so we're going to copy base and we're going to add that into the path at the top here and if we save that and reload the server you can see it's now starting up with no issues so this is just showing a way in which you can extract your middleware into its own module and then register or add that middleware in the main.py file to the app object by referencing That Base HTTP middleware now let's check that this is still working if we go back to the browser and on the video upload page I'm going to refresh this and we see we get the same output if we go back to to vs code you can see that we're getting that same message output as a log and that message is coming from the middleware so everything is still working but we've now managed to extract the middleware to its own file and this file can then be used basically for the roots in the application now let's go back to the better stack live tail for these logs and I'm going to open this out here so we can see it better this is one of the logs that we had and it contains that message where we have as the message basically some Json data all right I think this is the string version of that dictionary that we had we have a URL pointing to whatever URL generated the output and also a method but these are embedded within the dictionary we might want to get these as top level Keys such as the file name or the level so that we can then search for them as in this example at the top here where we search for all the logs that have a level equal to info so how do we extract this key value structure here from the message and embed those keys at the top level so they become searchable it turns out it's very easy to do this let's go back to middleware dop and when we output that log dictionary what we can do is we can actually pass the dictionary in as a keyword argument called extra so I'm going to do that just now and save this file and go back to one of the pages and generate these log outputs using the middleware if we then go back to better stack let's go back to the live tail that we have on the left hand side and we're going to scroll right to the bottom here and when we expand that log record we see that we get the same message but the keys and values within that log output have been extracted into top level keys and values such as URL here and we also have method of get here so we can then search for that for example at the top method and if we want to get only requests where the method is equal to get we can search for that and it's going to return that single record because now method is a top level key it's been index by better stack and we can now search over that content and we can see the output here now you can custom imiz these records as you'd like you could use Json data and Implement your own custom format or class but if you have simple keys and values that you want to appear in the top level and be searchable you can simply pass a dictionary as the extra key to the logger doino warn error and so on these methods all accept this extra parameter and it allows you to pass in the custom data that you need so let's finish this video by calculating the time it takes to generate a response for each of the end points in the application and we're going to do this in the middleware So within the middleware dopy file I'm going to go to the top and I'm going to import the time module that's built into Python's standard library and then right at the top of the middleware function I'm going to create a variable called start and I'm going to call the time.time method that's going to give us back a time stamp at which this middleware is first invoked and remember this will happen for every request that comes into the application so we have a start time and then what we do is we call this next function and await the response and that is going to give us back the response but we want to calculate the time it takes in order to generate that response so we can create another variable here just below the response and that's going to be called process time and again we're going to call the time. time function here and we're going to subtract the start time that we calculated at the start of this middleware function and that's going to give us back a Delta and that Delta represents the time it takes for this request to be processed and generate a response now the last thing I want to do is move these calls to logger doino down below the response here so after we generate the process time let's paste that code back in here we create the log dictionary and this time I'm going to add another key to that and it's going to be called process time and we're going to set that equal to the process time that we've calculated just above so that gives us our log dictionary we can then call logger doino and again we're outputting that dictionary as the message but we're also passing it to the extra key in order to make those keys in the dictionary top level keys on better stack let's now save this and go back to the page for the video upload we're going to refresh this and you can see we get back the response and if we do that on the main URL in the application we also get back the response we can go to the terminal and we can look at the process time for these and you can see it's a very small number for that main URL and also for the video upload URL also a very small number now what we're going to do is we're going to generate some artificial latency in one of these functions now when you upload a video that typically takes quite a long time so what I'm going to do at the top is I'm going to import the python async iio module this is built into Python's standard library and that contains a function that you can use in an asynchronous endpoint So within the upload videos endpoint let's await asyn do sleep and we're going to sleep for 1.5 seconds we can then go back to our endpoint here and I'm going to refresh this page and also go to upload videos here and you can see that that takes a little bit more time to process that request and generate the response and again if we go back to the terminal here and look at the process time that's been calculated by our middleware you can see that that is basically 1.5 seconds now what I'm going to do now just to end the video is go to better stack so let's go over to better Stack's UI here and go to the live tail now you might want to find the long running requests the slow requests in your application so let's now see how we can maybe do that now that we're logging out the process time on every single request if we look at the record at the very bottom here you can see the process time is now a top level key here and the value is the actual time taken to process that request so we can then search the logs for a process time and you can see the suggestions here better stack knows that that is a floating Point number we can then look for a processing time that's greater than 1 second and that would help us maybe diagnose very slow running requests in our application so let's search for those and we get back to results and these are results for the upload videos in end point after we introduced that ASN k. sleep call and you can see the process time is now 1.49 seconds so we can use these search values and it doesn't need to be an equality that we use we can search for values that are greater than a number or less than a number or if it's a string values that contain a substring so there are lots of options here on better stack and this is one example that you can use if you want to find slow running requests in a fast API application and similarly because we added the U to the top level Keys what we can also do at the top is we can look at the URL and that's a string as it says here but we can look for URLs that contain a particular string or are equal to a string so let's look for all logs at the URL upload videos and that's going to give us back all of those log outputs for that URL and again these have been generated by the middleware so that's all for this video in this video we've shown how to generate a fast API application that contains a logger into instance that sends your logs to different Handler locations with a particular format and we've seen how to add a Handler for better stack and send our logs to the better stack platform where you can effectively analyze them and find interesting incidents and outputs that are occurring in your application and in this video we also saw how to create a fast API middleware function that performs some kind of logic on every request response cycle in your application and then in this case it's generating some log output and sending that log output to better stack where we have analyzed it and found an endpoint in our application that's running slower than we would expect we can find that information and then respond to it accordingly and that's vital when you're building applications you need to know if something is performing slowly and then address that issue so thank you for watching this video if you've enjoyed the video please subscribe to the better stack Channel and please give the video a thumbs up if you've enjoyed this content if you have any suggestions for similar content please let us know in the comments and we'll see you in a future video

Channel: Better Stack

Views: 1,620

Keywords:

Id: 1RLFSOwpf88

Length: 31min 0sec (1860 seconds)

Published: Mon Dec 11 2023