Return logging to native Python

whensmybus.py

@@ -16,6 +16,7 @@
 buses and routes, checking the TfL bus API and formatting an appropriate reply to be sent back
 """
 # Standard libraries of Python 2.6
+import logging
 import re
 from math import sqrt
 from time import localtime
@@ -67,7 +68,7 @@ def parse_message(self, message):
         route_token_matches = [re.match(route_regex, r, re.I) for r in route_string.split(' ')]
         route_numbers = [r.group(0).upper() for r in route_token_matches if r]
         if not route_numbers:
-            self.log_debug("@ reply didn't contain a valid-looking bus number, skipping")
+            logging.debug("@ reply didn't contain a valid-looking bus number, skipping")
             return (None, None, None)
 
         return (route_numbers, origin, destination)
@@ -98,11 +99,11 @@ def process_individual_request(self, route_number, origin, destination, position
                     # run; if that stop has a sequence number greater than this stop then it's a valid route, so include this run 
                     relevant_stops = dict([(run, stop) for (run, stop) in relevant_stops.items() 
                                             if run in possible_destinations and possible_destinations[run].sequence > stop.sequence])
-                    self.log_debug("Successfully found a match for destination %s, filtering down to runs: %s", destination, relevant_stops.keys())
+                    logging.debug("Successfully found a match for destination %s, filtering down to runs: %s", destination, relevant_stops.keys())
 
             # We may not be able to find a destination, in which case - don't worry about this bit, and stick to unfiltered
             except WhensMyTransportException:
-                self.log_debug("Could not find a destination matching %s this route, skipping and not filtering results", destination)
+                logging.debug("Could not find a destination matching %s this route, skipping and not filtering results", destination)
 
         # If the above has found stops on this route, get data for each
         if relevant_stops:
@@ -127,9 +128,9 @@ def get_stops_by_geolocation(self, route_number, position):
             Values are BusStop objects
         """
         # GPSes use WGS84 model of Globe, but Easting/Northing based on OSGB36, so convert to an easting/northing
-        self.log_debug("Position in WGS84 determined as lat/long: %s %s", position[0], position[1])
+        logging.debug("Position in WGS84 determined as lat/long: %s %s", position[0], position[1])
         easting, northing = convertWGS84toOSEastingNorthing(position)
-        self.log_debug("Translated into OS Easting %s, Northing %s", easting, northing)
+        logging.debug("Translated into OS Easting %s, Northing %s", easting, northing)
 
         # A route typically has two "runs" (e.g. one eastbound, one west) but some have more than that, so work out how many we have to check
         self.geodata.execute("SELECT MAX(Run) FROM routes WHERE Route=?", (route_number,))
@@ -160,7 +161,7 @@ def get_stops_by_geolocation(self, route_number, position):
             if stop_data:
                 relevant_stops[run] = BusStop(Distance=sqrt(stop_data['dist_squared']), **stop_data)
 
-        self.log_debug("Have found stop numbers: %s", ', '.join([stop.number for stop in relevant_stops.values()]))
+        logging.debug("Have found stop numbers: %s", ', '.join([stop.number for stop in relevant_stops.values()]))
         return relevant_stops
 
     def get_stops_by_stop_number(self, route_number, stop_number):
@@ -175,7 +176,7 @@ def get_stops_by_stop_number(self, route_number, stop_number):
             raise WhensMyTransportException('bad_stop_id', stop_number)
 
         # Try and get a match on it
-        self.log_debug("Attempting to get an exact match on stop SMS ID %s", stop_number)
+        logging.debug("Attempting to get an exact match on stop SMS ID %s", stop_number)
         self.geodata.execute("SELECT Run, Sequence, Heading, Bus_Stop_Code, Stop_Name FROM routes WHERE Bus_Stop_Code=? AND Route=?",
                              (stop_number, route_number))
         stop_data = self.geodata.fetchone()
@@ -197,7 +198,7 @@ def get_stops_by_stop_name(self, route_number, origin):
 
         # First off, try to get a match against bus stop names in database
         # Users may not give exact details, so we try to match fuzzily
-        self.log_debug("Attempting to get a match on placename %s", origin)
+        logging.debug("Attempting to get a match on placename %s", origin)
         relevant_stops = {}
 
         # A route typically has two "runs" (e.g. one eastbound, one west) but some have more than that, so work out how many we have to check
@@ -213,28 +214,28 @@ def get_stops_by_stop_name(self, route_number, origin):
             if rows:
                 best_match = get_best_fuzzy_match(origin, rows, 'Stop_Name', get_bus_stop_name_similarity)
                 if best_match:
-                    self.log_info("Found stop name %s for Run %s via fuzzy matching", best_match['Stop_Name'], best_match['Run'])
+                    logging.info("Found stop name %s for Run %s via fuzzy matching", best_match['Stop_Name'], best_match['Run'])
                     relevant_stops[run] = BusStop(**best_match)
 
         # If we can't find a location for either Run 1 or 2, use the geocoder to find a location on that Run matching our name
         for run in (1, 2):
             if run not in relevant_stops and self.geocoder:
-                self.log_debug("No match found for run %s, attempting to get geocode placename %s", run, origin)
+                logging.debug("No match found for run %s, attempting to get geocode placename %s", run, origin)
                 geocode_url = self.geocoder.get_geocode_url(origin)
                 geodata = self.browser.fetch_json(geocode_url)
                 points = self.geocoder.parse_geodata(geodata)
                 if not points:
-                    self.log_debug("Could not find any matching location for %s", origin)
+                    logging.debug("Could not find any matching location for %s", origin)
                     continue
 
                 # For each of the places found, get the nearest stop that serves this run
                 possible_stops = [self.get_stops_by_geolocation(route_number, point).get(run, None) for point in points]
                 possible_stops = [stop for stop in possible_stops if stop]
                 if possible_stops:
                     relevant_stops[run] = sorted(possible_stops)[0]
-                    self.log_debug("Have found stop named: %s", relevant_stops[run].name)
+                    logging.debug("Have found stop named: %s", relevant_stops[run].name)
                 else:
-                    self.log_debug("Found a location, but could not find a nearby stop for %s", origin)
+                    logging.debug("Found a location, but could not find a nearby stop for %s", origin)
 
         return relevant_stops
 
@@ -267,15 +268,15 @@ def get_departure_data(self, relevant_stops, route_number):
                     hour = (int(scheduled_time[0:2]) + 1) % 24
                     scheduled_time = '%02d%s' % (hour, scheduled_time[2:4])
 
-                self.log_debug("Run %s, stop %s produced bus to %s %s", run, stop_name, arrival['destination'], scheduled_time)
+                logging.debug("Run %s, stop %s produced bus to %s %s", run, stop_name, arrival['destination'], scheduled_time)
                 time_info.append("%s to %s %s" % (stop_name, arrival['destination'], scheduled_time))
             else:
-                self.log_debug("Run %s, stop %s produced no buses", run, stop_name)
+                logging.debug("Run %s, stop %s produced no buses", run, stop_name)
                 time_info.append("%s: None shown going %s" % (stop_name, heading_to_direction(stop.heading)))
 
         # If the number of runs is 3 or 4, get rid of any "None shown"
         if len(time_info) > 2:
-            self.log_debug("Number of runs is %s, removing any non-existent entries", len(time_info))
+            logging.debug("Number of runs is %s, removing any non-existent entries", len(time_info))
             time_info = [t for t in time_info if t.find("None shown") == -1]
 
         return time_info

whensmydlr.py

@@ -16,6 +16,7 @@
 formatting an appropriate reply to be sent back
 """
 # Standard libraries of Python 2.6
+import logging
 import re
 from datetime import datetime, timedelta
 from pprint import pprint # For debugging
@@ -125,9 +126,9 @@ def get_departure_data(self, _line_code, station):
                     departure_delta = timedelta(minutes=(result.group(3) and int(result.group(3)) or 0))
                     departure_time = datetime.strftime(publication_time + departure_delta, "%H%M")
                     trains_by_platform[platform_name] = trains_by_platform[platform_name] + [DLRTrain(destination, departure_time)]
-                    self.log_debug("Found a train going to %s at %s", destination, departure_time)
+                    logging.debug("Found a train going to %s at %s", destination, departure_time)
                 else:
-                    self.log_debug("Error - could not parse this line: %s", train)
+                    logging.debug("Error - could not parse this line: %s", train)
 
         # Some platforms run trains the same way (e.g. at termini). DLR doesn't tell us if this is the case, so we look at the destinations
         # on each pair of platforms and see if there is any overlap, using the set object and its intersection function. Any such
@@ -136,7 +137,7 @@ def get_departure_data(self, _line_code, station):
         common_platforms =  [(plat1, plat2) for (plat1, plat2) in platform_pairs 
                              if set([t.destination for t in trains_by_platform[plat1]]).intersection([t.destination for t in trains_by_platform[plat2]])]
         for (plat1, plat2) in common_platforms[:1]:
-            self.log_debug("Merging platforms %s and %s", plat1, plat2)
+            logging.debug("Merging platforms %s and %s", plat1, plat2)
             trains_by_platform[plat1+plat2] = trains_by_platform[plat1] + trains_by_platform[plat2]
             del trains_by_platform[plat1]
             del trains_by_platform[plat2]

whensmytransport.py

@@ -92,7 +92,7 @@ def __init__(self, instance_name, testing=None, silent_mode=False):
             self.testing = config.get(self.instance_name, 'test_mode')
 
         if self.testing:
-            self.log_info("In TEST MODE - No Tweets will be made!")
+            logging.info("In TEST MODE - No Tweets will be made!")
 
         # Load up the databases for geodata & settings
         (_notused, self.geodata) = load_database('%s.geodata.db' % self.instance_name)
@@ -109,7 +109,7 @@ def __init__(self, instance_name, testing=None, silent_mode=False):
 
         # OAuth on Twitter
         self.username = config.get(self.instance_name,'username')
-        self.log_debug("Authenticating with Twitter")
+        logging.debug("Authenticating with Twitter")
         consumer_key = config.get(self.instance_name, 'consumer_key')
         consumer_secret = config.get(self.instance_name, 'consumer_secret')
         key = config.get(self.instance_name, 'key')
@@ -141,19 +141,7 @@ def setup_logging(self, silent_mode, debug_level):
             rotator.setFormatter(logging.Formatter('%(asctime)s %(levelname)-8s %(message)s'))
             logging.getLogger('').addHandler(console)
             logging.getLogger('').addHandler(rotator)
-            self.log_debug("Initializing...")
-
-    def log_info(self, message, *args):
-        """
-        Wrapper for debugging at the INFO level
-        """
-        logging.info(message, *args)
-
-    def log_debug(self, message, *args):
-        """
-        Wrapper for debugging at the DEBUG level
-        """
-        logging.debug(message, *args)
+            logging.debug("Initializing...")
 
     def get_setting(self, setting_name):
         """
@@ -188,7 +176,7 @@ def check_followers(self):
         last_follower_check = self.get_setting("last_follower_check") or 0
         if time.time() - last_follower_check < 600:
             return
-        self.log_info("Checking to see if I have any new followers...")
+        logging.info("Checking to see if I have any new followers...")
         self.update_setting("last_follower_check", time.time())
 
         # Get IDs of our friends (people we already follow), and our followers
@@ -211,10 +199,10 @@ def check_followers(self):
         for twitter_id in twitter_ids_to_follow[::-1]:
             try:
                 person = self.api.create_friendship(twitter_id)
-                self.log_info("Following user %s", person.screen_name )
+                logging.info("Following user %s", person.screen_name )
             except tweepy.error.TweepError:
                 protected_users_to_ignore.append(twitter_id)
-                self.log_info("Error following user %s, most likely the account is protected", twitter_id)
+                logging.info("Error following user %s, most likely the account is protected", twitter_id)
                 continue
 
         self.update_setting("protected_users_to_ignore", protected_users_to_ignore)
@@ -242,9 +230,9 @@ def check_tweets(self):
 
         # No need to bother if no replies
         if not tweets and not direct_messages:
-            self.log_info("No new Tweets, exiting...")
+            logging.info("No new Tweets, exiting...")
         else:
-            self.log_info("%s replies and %s direct messages received!" , len(tweets), len(direct_messages))
+            logging.info("%s replies and %s direct messages received!" , len(tweets), len(direct_messages))
 
         for tweet in direct_messages + tweets:
 
@@ -288,20 +276,20 @@ def validate_tweet(self, tweet):
 
         # Bit of logging, plus we always return True for DMs
         if is_direct_message(tweet):
-            self.log_info("Have a DM from %s: %s", tweet.sender.screen_name, message)
+            logging.info("Have a DM from %s: %s", tweet.sender.screen_name, message)
             return True
         else:
             username = tweet.user.screen_name
-            self.log_info("Have an @ reply from %s: %s", username, message)
+            logging.info("Have an @ reply from %s: %s", username, message)
 
         # Don't start talking to yourself
         if username == self.username:
-            self.log_debug("Not talking to myself, that way madness lies")
+            logging.debug("Not talking to myself, that way madness lies")
             return False
 
         # Ignore mentions that are not direct replies
         if not message.lower().startswith('@%s' % self.username.lower()):
-            self.log_debug("Not a proper @ reply, skipping")
+            logging.debug("Not a proper @ reply, skipping")
             return False
 
         return True
@@ -311,7 +299,7 @@ def get_tweet_geolocation(self, tweet, user_request):
         Ensure any geolocation on a Tweet is valid, and return the co-ordinates as a (latitude, longitude) tuple
         """
         if hasattr(tweet, 'geo') and tweet.geo and tweet.geo.has_key('coordinates'):
-            self.log_debug("Detect geolocation on Tweet")
+            logging.debug("Detect geolocation on Tweet")
             position = tweet.geo['coordinates']
             easting, northing = convertWGS84toOSEastingNorthing(position)
             gridref = gridrefNumToLet(easting, northing)
@@ -370,12 +358,12 @@ def send_reply_back(self, reply, username, send_direct_message=False, in_reply_t
         for message in messages:
             try:
                 if send_direct_message:
-                    self.log_info("Sending direct message to %s: '%s'", username, message)
+                    logging.info("Sending direct message to %s: '%s'", username, message)
                     if not self.testing:
                         self.api.send_direct_message(user=username, text=message)
                 else:
                     status = "@%s %s" % (username, message)
-                    self.log_info("Making status update: '%s'", status)
+                    logging.info("Making status update: '%s'", status)
                     if not self.testing:
                         self.api.update_status(status=status, in_reply_to_status_id=in_reply_to_status_id)
 
@@ -432,7 +420,7 @@ def process_wmt_exception(self, exc):
         """
         Turns a WhensMyTransportException into a message for the user
         """
-        self.log_debug("Exception encountered: %s" , exc.value)
+        logging.debug("Exception encountered: %s" , exc.value)
         return "Sorry! %s" % exc.value
 
     def alert_admin_about_exception(self, tweet, exception_name):
@@ -527,8 +515,8 @@ def report_twitter_limit_status(self):
         Helper function to log what our Twitter API hit count & limit is
         """
         limit_status = self.api.rate_limit_status()
-        self.log_info("I have %s out of %s hits remaining this hour", limit_status['remaining_hits'], limit_status['hourly_limit'])
-        self.log_debug("Next reset time is %s", (limit_status['reset_time']))
+        logging.info("I have %s out of %s hits remaining this hour", limit_status['remaining_hits'], limit_status['hourly_limit'])
+        logging.debug("Next reset time is %s", (limit_status['reset_time']))
 
 
 class RailStation():
@@ -593,9 +581,9 @@ def get_station_by_geolocation(self, line_code, position):
         """
         #pylint: disable=W0613
         # GPSes use WGS84 model of Globe, but Easting/Northing based on OSGB36, so convert to an easting/northing
-        self.log_debug("Position in WGS84 determined as lat/long: %s %s", position[0], position[1])
+        logging.debug("Position in WGS84 determined as lat/long: %s %s", position[0], position[1])
         easting, northing = convertWGS84toOSEastingNorthing(position)
-        self.log_debug("Translated into OS Easting %s, Northing %s", easting, northing)
+        logging.debug("Translated into OS Easting %s, Northing %s", easting, northing)
 
         # Do a funny bit of Pythagoras to work out closest stop. We can't find square root of a number in sqlite
         # but then again, we don't need to, the smallest square will do. Sort by this column in ascending order
@@ -614,7 +602,7 @@ def get_station_by_geolocation(self, line_code, position):
         self.geodata.execute(query)
         row = self.geodata.fetchone()
         if row:
-            self.log_debug("Have found %s station (%s)", row['Name'], row['Code'])
+            logging.debug("Have found %s station (%s)", row['Name'], row['Code'])
             return RailStation(**row)
         else:
             return None
@@ -625,18 +613,18 @@ def get_station_by_station_name(self, line_code, origin):
         """
         # First off, try to get a match against station names in database
         # Users may not give exact details, so we try to match fuzzily
-        self.log_debug("Attempting to get a match on placename %s", origin)
+        logging.debug("Attempting to get a match on placename %s", origin)
         self.geodata.execute("""
                              SELECT Name, Code, Location_Easting, Location_Northing FROM locations WHERE Line=? OR Line='X'
                              """, (line_code,))
         rows = self.geodata.fetchall()
         if rows:
             best_match = get_best_fuzzy_match(origin, rows, 'Name', get_rail_station_name_similarity)
             if best_match:
-                self.log_debug("Match found! Found: %s", best_match['Name'])
+                logging.debug("Match found! Found: %s", best_match['Name'])
                 return RailStation(**best_match)
 
-        self.log_debug("No match found for %s, sorry", origin)
+        logging.debug("No match found for %s, sorry", origin)
         return None
 
 def abbreviate_station_name(station_name):