NetReconToolkit – Part 03

Series Navigation

<< NetReconToolkit – Part 02          NetReconToolkit – Part 04 >>

Getting this right from the outset will (almost) ensure a successful program … what is this magical ingredient? Is it click bait? Is it fairy dust? lambda expressions? machine learning? No … it’s logging (woo hoo!!). Was that a bit of a letdown?

What I used to do

I used to write my own functions to handle logging (you’re probably thinking “what a weirdo” and you’d be right) or just used a bunch of print() statements.

My print statements looked something like this:

print(datetime.now().strftime("%d/%m/%Y %H:%M:%S") + ": Started doing something useful")

And were sprinkled around my code (just like fairy dust), but were ultimately burdensome and almost useless. There would either be too many messages, not enough, or just useless details.

My logging function basically did the same thing, but I didn’t need to re-state common variables, like my datetime stamp.

def awesome_logging_function(message):
    print(datetime.now().strftime("%d/%m/%Y %H:%M:%S") + ": " + message)

As you’ve probably already guessed … neither approach worked well.

The Holy Grail has been found!

How’s that for a section heading!?

Python has a package called “logging” which, when imported, will allow you to call the following function anywhere in your code (cool huh?):

import logging

logging.info("This is a message to log")

Now, I know that’s not Holy Grail-level special, so let’s add a few more bits. I put all this stuff right after my last import statement in my main python file:

import logging
import logging.handlers

log_filename = 'Awesome_Application.log'
log_rotate_handler = logging.handlers.RotatingFileHandler(log_filename, maxBytes=100000, backupCount=5)
logging.basicConfig(format='%(asctime)s %(message)s', handlers=[log_rotate_handler], level=logging.DEBUG)

A few notes:

• log_filename: That’s the name of the file you want to log to
• log_rotate_handler: Here we define one of the extra-special bits of logging. A RotatingFileHander … which takes the following arguments:
  • The log_filename (that’d be “Awesome_Application.log”).
  • The maximum size each log can grow to in bytes (10 KB in this case).
  • The number of backup files you want to keep before deleting the oldest one.
• logging.basicConfig: Configuring logging is dead simple.
  • format=’%(asctime)s %(message)s’: This formats my message by adding a timestamp first and then the message.
  • handlers: This takes an array as an argument, since you can have more than one handler. In this case it’s the RotatingFileHandler defined above (all alone …).
  • level: What do you want to log? Debug is the most granular while Critical is the least … a handy reference:
    • Debug: Log all the things
    • Info: Log some of the things
    • Warning: Log all the interesting stuff
    • Error: Log some of the interesting stuff
    • Critical: Log only explosions

The cool part is that log level can be changed (either by you or the user, if you want them to). If I changed this from Debug to Info, then any time I call:

logging.debug("Some message") 

It wouldn’t appear in my log, so I put logging.debug messages after every line of code (that’s why it’s called debug!)

As you can probably tell, the logging level functions as a hierarchy, anything at the logging level, or above, will get written to the file. Anything below, will get ignored.

A quiz (just to make sure you’re paying attention):

• Setting the logging level to Error will do what?
  1. Log only logging.error calls
  2. Log everything
  3. Log only logging.error and logging.critical calls
  4. Log only logging.warning, logging.info, and logging.debug calls
  5. Log nothing

And the answer is … 3! Log only logging.error and logging.critical calls (good job, go and get a juice box).

Now you know how to log … but wait, there’s more!

Extra, extra, read all about it!

Do you use functions in your code? If not, you need to get another job …

How does that play into logging you ask? (I’ll assume that you just asked that question out loud)

Well, wouldn’t it be nice to know what function you where in when the log was written to? I think so. Enter the following bit of code:

import inspect

def awesome_function():
    current_function_name = inspect.getframeinfo(inspect.currentframe()).function
    logging.info('%s - Entering function', current_function_name)

I put this right after I define a function (any function, no exceptions) and the logging call is always set to Info so I can set my log level to info and see these messages, but not see all the debug stuff.

This will do the following:

• current_function_name: The inspect package will get currentframe as an object, pass it to getframeinfo and return the name of the function that it’s running in. This is better than hard-coding your function names into the logging call (what happens when you change your function name and don’t update the hard-coded value, huh?).
• logging.info: Use current_function_name as a variable when writing to the log.

Doing this ensures that your log will always show what function you’re in … very very very helpful when trying to figure out why your code just died (I know, that probably only happens to me).