 Okay, so a good afternoon everyone. My name is James Dennis. I am a software engineer at zero stack I have been a Python developer for probably about eight years now and Here to talk about some Python basics, which I think are pretty useful to know when you're operating zero open stack So how many Python? Like if we have any Python like developers here who have done any Python at all Okay. All right. Good. Okay, so let's go ahead and get started. So Obviously, there's a lot of stuff you could talk about when you're trying to talk about basics here So what I what I've come up with here is is you know some topics. I think are most useful So we'll talk a little bit about Python itself as a language just briefly and then move on to the Python logging framework, which is pretty much what every Python Application on the planet uses because it's so fully developed and then Threading models which are used in applications Primarily, we're going to talk about these because it affects logging, you know And so you can try and figure out, you know, what's what's going on when you when you do that You know, those of us who work with open stack We're quite familiar with the Python backtrace stack trace that appears in the logs So we're going to go over one of those and so you can learn how to read it and Get some useful information out it and also how you can actually add some additional logging yourself to the code in Say you've reproduced the the issue in a test environment and You want to add some additional logging because in some of the variables that you need to figure out what's actually going on It's not present Okay, okay, so Python. It's a dynamic interpreted language If there is a bytecode intermediary format PYC files, which you're probably familiar with you've seen But for all intents and purposes, it's it's an interpreted language. It's object oriented So things typically applications are written with classes. It doesn't have to be but you know any large application That's how they do it use inheritance so that you can reuse common code for different types Exceptions are used for our handling. I'll talk about those And one of the things that most people who aren't familiar with Python think are a little strange at first is that there's no curly braces That indentation is used to mark like the control block for like while loops or you know for loops stuff like that So Python's been going through a transition since 2008 which is not quite as bad as Pearl 6 I suppose but it's been going on for a while And essentially what happened is is that there are you know, Python is known as a language is fairly easy to read And kind of tries to make sense When it when it's read and there was a couple of things in the language which you know They thought they could approve upon and one of them being all strings by default in Python 3 are unicode and Python 2 there's not so a few changes like that meant that the language It was not possible just to take Python 2 code and run it on Python 3 So that meant that people have been slowly porting things towards and this is something that OpenStack has been working towards There's a link there that you can go to and you can read about their progress so far and So when you're reading online about Python 2 Python 3 most deployments, I would expect If not all of them are currently using Python 2 2.7 is the latest release like they do keep coming out with point releases like less than that like 2.7 point 11 for security issues, but the Benevolent dictator for life Guido who runs Python. He says there is not going to be a Python 2.8 Okay Okay, so how how are Python modules applications actually structured so they're structured into modules and packages a module is single file that dot pi file, which is a collection of definitions and statements actually the core logic and then a package is a collection of modules which are held under a directory and What you can actually do you put packages inside of packages and you can you can build this hierarchy of functionality so the example that I given here which I took out of the Python documentation is you've got sound dot effects dot echo so Echo is the the dot pi file and sound and effects of these directories So when Python code has an import statement in it What it has to do is it has to go to the file system And it has to try and find a file a module that matches that structure that you've given it into the import statement So the way that it does that is it has certain Locations that it's going to look for those directories and those files in and that's controlled by this sys dot path Variable which is built into Python and so the the example of it's a list You can actually manipulate it in Python code to if you wanted to add additional directories to be searched for So the example which I'm giving here is actually what what you see on Ubuntu and specifically the open stack packages are in that Dist packages which is like the penultimate entry in the list there So typically that's where you'll find Nova and neutron and stuff like that if you're trying to find a source code Okay, so what does an import statement look like so I've given two examples here They do import they do look for the files in the same place Really what the difference is between these two is how you then access that module in the code itself So with the first import statement if you wanted to get to that echo effect Class that I that I put there as an example. You'd actually have to put sound dot effects dot echo dot echo effect so the second one is sort of a way to Import echo directly without having to do all that typing. So this example we have, you know a class called echo effect and It's located in that location there. So the import Python when it's on my import statement It's searched through and it found that location So the other place where this is like this is useful to know with open stack is that you've probably when Configuring no broad neutron sometimes you have this concept of a driver and you've gone to some documentation It tells you put this long string with dots in and that will make it work, right? So this is actually what's going on under the hood is that it's turning that into an import statement followed by a class so This one here the network API class Which is a driver in Nova what it does is it goes to that location on disk and it instantiates that API class and That API class implements certain methods that Nova expects Okay So I was saying earlier is Python has an extensive logging module In fact, it has three chapters in the Python documentation and just shipping with the standard library Which every Python installation have there are 16 different ways to handle logs that are generated, right? So I put three examples up here You know some of them are derived from the others. So I suppose 16 is a little bit A bit exaggeration, but there really are 16 classes. So you can configure everything from Just saving a file to a disk to writing your own or having them sent to an HTTP server By default open stack uses one called the file watch handler, which is a one the logs to disk But is also good for using with log rotation All right, so locking levels So the log levels open stack users again, I've derived from the Python logging package apart from the trace one Which which they added which is typically used for for trace backs So critical is the lease verbose So that's saved for really bad things. I'm not sure I've ever seen Open stack emitter critical typically I see errors and traces and then debug is the is the most verbose So if you really want to get a good idea of what's going on like what decisions Nova scheduler is making or something like that Then really you want to get that debug level so one of the one of the Powerful things and also sometimes think something that people complain about with Python about the complexity logging module is the fact that Loggers themselves actually exist in a hierarchy much like packages and What this allows you to do is actually to configure Different log levels for different parts of the hierarchy So for instance this hierarchy here, which I which I presented example. I could say that I want You know Nova dot API to open stack to have debug level But I want Nova actually to remain like a critical or something like that And you can sort do the same thing with handlers if you want a log handler Which sends a notification to a server to only process errors then you can do that you can set the error level you the debug log level to error and that handler will only handle the error and It's sort of invisible in the hierarchy, but it's there is that it's the the root logger So when you're specifying verbose and debug in your open stack configuration files What it's really doing is it's telling the root logger I want everything to be logged at this level and unless a setting is set somewhere further down in the hierarchy for a particular module that will Be the level that everything bugs at So there is some open stack specific configuration that occurs and This is centralized in Oslo log, which is shared among all of the services that I looked at And what this because the Python loggy module so flexible There are no certain things application needs to do to set it up where it might want to read a configuration file from Stuff like that. So it makes sense. It's centralized so So the basic log in configuration, which is I imagine what the majority people use you have these two flags verbose and debug and One one note I noticed when going through the code for this is that if you set verbose to true and debug to true you'll end up at the info level not the debug level because the way that the Code is written. It sets the root logger to Info checking the verbose flag after it's actually set the debug one. So so watch out for that one and After it set that root logger level it will actually Apply all of these things called the default log levels. So this this list here is this like key value list what this what this has in it is logger identifiers in that hierarchy I was talking about and and What level they should be at so what this means is that if you tweak the debug or the verbose flags that's not actually going to affect the logging levels of these things that are listed down the bottom here and One time that that this affected me actually is when I was doing some rabid MQ debugging I was trying to understand what was going on with Oslo messaging and if you see on the list there Oslo messaging is actually set to info. So the verbose and debug flags have no effect so what you can do is you can you can set this default log levels setting on in any of the configuration files and And therefore you could you could set it as blank and you get debug for every single module That's probably not a good idea, but you can take the default and you can tweak it Okay, so one of the other things that you can do is there's this setting called log config append and if you set this you set it to a path to a logging I and I file and What this does is is that the Oslo config the verbose the deep so Oslo logging The debug flag the verbose flag. They're not actually they don't take effect They did and neither does those default log levels for all those other modules all of the logging configuration is read out of the configuration file Now I've seen in some open stack Services, they actually have an example of a file which you can use if not. It's actually just a standard Python logging module configuration file if you look at the Python documentation it there's a whole tutorial Excuse me on how to use it and you know even in your own Python programs. You can use it It's like a single call your import logging your logging dot com fig dot file com fig give it the path and then it'll pull it in So if you really need to get fine tuning on your logging and then this is what you could do And also this is the mechanism that you could install other logging handlers So if we talk like I said earlier if you wanted to set up like a logging handler that makes an HTTP call Or something like that then that this is the most flexible method to configure logging you can do anything you can do a logging method Python logging with this Okay, so moving off from logging for a bit So Python Uses exceptions for errors So the way that these work is that somewhere in the code, you know after many function calls It detects a problem. Maybe the Python runtime itself detects a problem It will raise an exception and that exception will actually filter up through the stack It's unwound until an accept block is found So I've given quite a kind of a simple contrived Example here, so we have a try block inside that I make this function call called show data Then somewhere down in the depths of show data it connects to the database, right? but if it has a problem connecting it will raise an exception and The accept database error there Will receive that and so I'm using the logging library here It has this dot exception method and that will actually print the trace back to the screen in any other any method there That's kind of a basic overview of exceptions So that show data here. I mean This is this will help when we come to talk it about Stack traces or back traces. They're the same thing Here's a here's an example of the stack that's occurring with The call to show data So if you can imagine you call show data show data knows that there's a number of fields So it calls show field for a specific field just think we've got we've got a loop going on there And it's calling show field so it has to get the information for that field then it connects to the database So in the example I gave earlier with the database not being able to connect What happens is connect to db raises an exception The at the stack unwinds all the way back to where I called show data and then that ends up getting logged So a back trace. Okay, so this is obviously something that's not too easy Just to throw on a slide, but what I've actually made this smaller than expected And I've stripped out a few lines but to point out some important things on this one here So as it says at the top the most recent call is is the last call So if we go right to the bottom there You can see that where the exception occurred it was a connection refused So like how did we get there? So we go back up to the top? This is the entry point now. This is an over API call So we went into this we were handled by a function called double underscore in python terminology That's called Dunder so in this Dunder call function in this init And then what happened is is that if you look down the list here You can see it went into the security groups module it then went into the neutron driver It went into the neutron client what so it's about to make a call to to neutron went into the keystone client Which is because the keystone client actually implements a bunch of base functionality that all the clients have But it gives you the context and then finally it made a call to Neutron which failed so what you can deduce really from the trace back here Is that the operation that was being performed is wanted to get some security group information or perhaps set a security group and So it executed an instantiated a neutron driver and then and fell so that's the sort of information that you can get from from the trace back You know what service it was trying to connect to and and why and the other thing it does you you can see here Is it tells you exactly what python module? Was actually making the call to what line and then when you look at that line You'll see where it makes the function called to that to the next piece of the the back trace So if you want to add additional logging message and messages So this this first line at the top here logger get logger So this is the bit where it builds that hierarchy So done the name in python is a special variable which is the package location in the module So what that ends up making sure is is that and most open stack packages do this I think all of them actually is that the logger for a particular module is the same as the package hierarchy So you know how to set it So in this example and this is actually based on the trace back Which I had previously this is where it was generated that the raise line is actually the exception is is that And I actually ran into this myself as is that the connection refuse message doesn't actually contain Any information about what the request library connection error was because connection refuse doesn't actually necessarily mean like a TCP connection refused It was actually pretty much any kind of connection error got turned into connection refused So adding log error there meant that then when I reproduced the issue that then I got the actual additional information So that's like a situation in which adding additional logging is useful and because it's python You don't need to read Recompile it or anything on your test system You can just edit the file right there in use live python 2.7 Restart the service and and hopefully you'll get the information that you need Okay, so Execution models This is a fairly complex topic, but I think it's important when you're reading your log files So you know to kind of give an overview you typically have these three different execution models apply to any program any language You have multi-process Where you know you do ps and your Linux box you see multiple processes or any requests can be handled by any of them Normally when a request comes in maybe that calls out to the database that process will be blocked until the response comes back But you can do things in parallel right not just concurrently, but they can run simultaneously on multiple CPUs Now multi-threaded is Similar to multi-process. It's an operating system provided mechanism. They actually all the threads share Memory they all run inside the virtual same virtual memory space Which has performance benefits when it comes to exchanging information between threads But it also has the downside that when two threads are working with the same thing sometimes you have to perform synchronization Python is not very good at multi-threading due to the design of the interpreter Which you know, it's a very long topic and you can find hundreds of people flaming about it online and Trying to figure out what to do about it. So but greenlets They're actually something which you build at the application layer It's nothing to do with the operating system and this is a cooperative multi-tasking So what happens is you get a coroutine, which is like a special function Which gets called and then at some point it tries to make it IO or it's decided doesn't need to do anything else It called sleep and that passes control to another function. So this gives you Concurrency because you're doing multiple things at once, but it only uses normally one thread or one process So they're not actually running in parallel so Why is that important? Okay, so it's about the logging right when you look at your logs you could actually be looking at things that happened at the same time and It can be difficult to figure out what's going on now. There's there are some solutions for some of these and there I right now that doesn't seem to be a good solution for the Cooperative the cooperative multi-tasking that the Greenlit mechanism now open stack services typically do use that Greenlit mechanism That's like the number one used mechanism for concurrency Apart from a keystone recently deprecated that now there they recommend that you run it under Apache whiskey, which will actually use a multi-process and a multi-threaded model So when you're looking at the logs you win a multi-process system like something running like Keystone You'll actually get the PID which I put in I put in bold under multi-process there So that's one way in which you can tell that you're looking at two different requests so by default it doesn't log opens stack doesn't log the thread ID, but again, the Python log it has this concept of a Formatter and that's something you can set with that configuration file that I was talking about earlier and you and if you look at the Python Documentation, there's one called thread if you add that to your logging formatter Then you can also get some some thread information and also one thing which Oslo log has added so to try and make this problem To try and solve this problem make this easier for people is that if it has any contextual information Which is being passed but from the logger like the instance or the project or something like that that will be added into the into the log output as well Okay, so if anyone has any questions and go up to the microphone and That's it all right Yes, they will be Have a question just a short one. Can you get me back to slide 15? Sure Hopefully so here we have the message creation this underscore operator. Is it for localization? I'm sorry, which we've got the what are we talking about here? Sorry Yeah, the word where you say message equals unable to establish the connection. So it's underscore parenthesis stuff What this underscore here? Yeah, it is for localization. Yes. That's right This is actually what's what's not in bold the unbolded stuff is what the original code was there. So that's yeah, that's open stack Localization support so because I threw this error in like myself, you know, I didn't really worry about localization or anything So I just all right. Thanks very much everyone