commit d55d7d74122e1f07df608f653541c45a154ce49c Author: ilv ilv@users.noreply.github.com Date: Mon Aug 3 15:02:27 2015 -0300

Debugging improvements --- gettor/blacklist.py | 85 +++++++++++------- gettor/core.py | 241 ++++++++++++++++++++++++++++----------------------- gettor/db.py | 76 ++++++++++------ gettor/utils.py | 19 ++++ 4 files changed, 258 insertions(+), 163 deletions(-)

diff --git a/gettor/blacklist.py b/gettor/blacklist.py index b95d888..a16c764 100644 --- a/gettor/blacklist.py +++ b/gettor/blacklist.py @@ -27,6 +27,14 @@ class BlacklistError(Exception): pass

+class ConfigError(Exception): + pass + + +class InternalError(Exception): + pass + + class Blacklist(object): """Manage blacklisting of users.

@@ -38,6 +46,7 @@ class Blacklist(object):

ConfigurationError: Bad configuration. BlacklistError: User is blacklisted. + InternalError: Something went wrong internally.

"""

@@ -47,44 +56,46 @@ class Blacklist(object): :param: cfg (string) path of the configuration file.

""" - # define a set of default values - DEFAULT_CONFIG_FILE = 'blacklist.cfg' - - logging.basicConfig(format='[%(levelname)s] %(asctime)s - %(message)s', - datefmt="%Y-%m-%d %H:%M:%S") - log = logging.getLogger(__name__) + default_cfg = 'blacklist.cfg' config = ConfigParser.ConfigParser()

if cfg is None or not os.path.isfile(cfg): - cfg = DEFAULT_CONFIG_FILE - - config.read(cfg) + cfg = default_cfg

try: - dbname = config.get('general', 'db') - self.db = db.DB(dbname) - except ConfigParser.Error as e: - raise ConfigError("Couldn't read 'db' from 'general'") + with open(cfg) as f: + config.readfp(f) + except IOError: + raise ConfigError("File %s not found!" % cfg)

try: + dbname = config.get('general', 'db') logdir = config.get('log', 'dir') logfile = os.path.join(logdir, 'blacklist.log') - except ConfigParser.Error as e: - raise ConfigError("Couldn't read 'dir' from 'log'") - - try: loglevel = config.get('log', 'level') + self.db = db.DB(dbname) + except ConfigParser.Error as e: - raise ConfigError("Couldn't read 'level' from 'log'") + raise ConfigError("%s" % e) + except db.Exception as e: + raise ConfigError("%s" % e)

- # establish log level and redirect to log file - log.info('Redirecting logging to %s' % logfile) + # logging + log = logging.getLogger(__name__) + + logging_format = utils.get_logging_format() + date_format = utils.get_date_format() + formatter = logging.Formatter(logging_format, date_format) + + log.info('Redirecting BLACKLIST logging to %s' % logfile) logfileh = logging.FileHandler(logfile, mode='a+') + logfileh.setFormatter(formatter) logfileh.setLevel(logging.getLevelName(loglevel)) log.addHandler(logfileh)

# stop logging on stdout from now on log.propagate = False + self.log = log

def is_blacklisted(self, user, service, max_req, wait_time): """Check if a user is blacklisted. @@ -113,24 +124,40 @@ class Blacklist(object): if r: # permanently blacklisted if r['blocked']: - self.db.update_user(user, service, r['times']+1, 1) - raise BlacklistError("Blocked user") + try: + self.db.update_user(user, service, r['times']+1, 1) + raise BlacklistError("Blocked user") + except db.DBError as e: + raise InternalError("Can't update user (%s)" % str(e)) # don't be greedy elif r['times'] >= max_req: - last = datetime.datetime.fromtimestamp(float( - r['last_request'])) + last = datetime.datetime.fromtimestamp( + float(r['last_request']) + ) next = last + datetime.timedelta(minutes=wait_time)

if datetime.datetime.now() < next: # too many requests from the same user - self.db.update_user(user, service, r['times']+1, 0) - raise BlacklistError("Too many requests") + try: + self.db.update_user(user, service, r['times']+1, 0) + raise BlacklistError("Too many requests") + except db.DBError as e: + raise InternalError("Can't update user (%s)" % str(e)) else: # fresh user again! - self.db.update_user(user, service, 1, 0) + try: + self.db.update_user(user, service, 1, 0) + except db.DBError as e: + raise InternalError("Can't update user (%s)" % str(e)) else: # adding up a request for user - self.db.update_user(user, service, r['times']+1, 0) + try: + self.db.update_user(user, service, r['times']+1, 0) + except db.DBError as e: + raise InternalError("Can't update user (%s)" % str(e)) else: # new request for user - self.db.add_user(user, service, 0) + try: + self.db.add_user(user, service, 0) + except db.DBError as e: + raise InternalError("Can't add new user (%s)" % str(e)) diff --git a/gettor/core.py b/gettor/core.py index df596a9..219fed2 100644 --- a/gettor/core.py +++ b/gettor/core.py @@ -27,11 +27,7 @@ class ConfigError(Exception): pass

-class UnsupportedOSError(Exception): - pass - - -class UnsupportedLocaleError(Exception): +class NotSupportedError(Exception): pass

@@ -60,8 +56,7 @@ class Core(object):

Exceptions:

- UnsupportedOSError: Request for an unsupported operating system. - UnsupportedLocaleError: Request for an unsupported locale. + UnsupportedOSError: OS and/or locale not supported. ConfigError: Something's misconfigured. LinkFormatError: The link added doesn't seem legit. LinkFileError: Error related to the links file of a provider. @@ -77,71 +72,56 @@ class Core(object): or if something goes wrong while reading options from it.

""" - # define a set of default values - DEFAULT_CONFIG_FILE = 'core.cfg' - - logging.basicConfig(format='[%(levelname)s] %(asctime)s - %(message)s', - datefmt="%Y-%m-%d %H:%M:%S") - log = logging.getLogger(__name__) + default_cfg = 'core.cfg' config = ConfigParser.ConfigParser()

if cfg is None or not os.path.isfile(cfg): - cfg = DEFAULT_CONFIG_FILE - - config.read(cfg) - - try: - basedir = config.get('general', 'basedir') - except ConfigParser.Error as e: - raise ConfigError("Couldn't read 'basedir' from 'general'") - - try: - dbname = config.get('general', 'db') - dbname = os.path.join(basedir, dbname) - self.db = db.DB(dbname) - except ConfigParser.Error as e: - raise ConfigError("Couldn't read 'db' from 'general'") + cfg = default_cfg

try: - self.linksdir = config.get('links', 'dir') - self.linksdir = os.path.join(basedir, self.linksdir) - except ConfigParser.Error as e: - raise ConfigError("Couldn't read 'links' from 'dir'") + with open(cfg) as f: + config.readfp(f) + except IOError: + raise ConfigError("File %s not found!" % cfg)

try: self.supported_lc = config.get('links', 'locales') - except ConfigParser.Error as e: - raise ConfigError("Couldn't read 'locales' from 'links'") - - try: self.supported_os = config.get('links', 'os') - except ConfigParser.Error as e: - raise ConfigError("Couldn't read 'os' from 'links'")

- try: - loglevel = config.get('log', 'level') - except ConfigParser.Error as e: - raise ConfigError("Couldn't read 'level' from 'log'") - - try: + basedir = config.get('general', 'basedir') + self.linksdir = config.get('links', 'dir') + self.linksdir = os.path.join(basedir, self.linksdir) self.i18ndir = config.get('i18n', 'dir') - except ConfigParser.Error as e: - raise ConfigError("Couldn't read 'dir' from 'i18n'")

- try: + loglevel = config.get('log', 'level') logdir = config.get('log', 'dir') logfile = os.path.join(logdir, 'core.log') + + dbname = config.get('general', 'db') + dbname = os.path.join(basedir, dbname) + self.db = db.DB(dbname) + except ConfigParser.Error as e: - raise ConfigError("Couldn't read 'dir' from 'log'") + raise ConfigError("Configuration error: %s" % str(e)) + except db.Exception as e: + raise InternalError("%s" % e)

- # establish log level and redirect to log file - log.info('Redirecting logging to %s' % logfile) + # logging + log = logging.getLogger(__name__) + + logging_format = utils.get_logging_format() + date_format = utils.get_date_format() + formatter = logging.Formatter(logging_format, date_format) + + log.info('Redirecting CORE logging to %s' % logfile) logfileh = logging.FileHandler(logfile, mode='a+') + logfileh.setFormatter(formatter) logfileh.setLevel(logging.getLevelName(loglevel)) log.addHandler(logfileh)

# stop logging on stdout from now on log.propagate = False + self.log = log

def _get_msg(self, msgid, lc): """Get message identified by msgid in a specific locale. @@ -153,11 +133,14 @@ class Core(object):

""" # obtain the content in the proper language - t = gettext.translation(lc, self.i18ndir, languages=[lc]) - _ = t.ugettext + try: + t = gettext.translation(lc, self.i18ndir, languages=[lc]) + _ = t.ugettext

- msgstr = _(msgid) - return msgstr + msgstr = _(msgid) + return msgstr + except IOError as e: + raise ConfigError("%s" % str(e))

def get_links(self, service, os, lc): """Get links for OS in locale. @@ -170,27 +153,33 @@ class Core(object): :param: os (string) the operating system. :param: lc (string) tthe locale.

- :raise: UnsupportedOSError if the operating system is not supported. - :raise: UnsupportedLocaleError if the locale is not supported. :raise: InternalError if something goes wrong while internally.

:return: (string) the links.

""" - + # english and windows by default if lc not in self.supported_lc: - raise UnsupportedLocaleError("Locale %s not supported" % lc) + self.log.debug("Request for locale not supported. Default to en") + lc = 'en'

if os not in self.supported_os: - raise UnsupportedOSError("OS %s not supported " % os) + self.log.debug("Request for OS not supported. Default to windows") + os = 'windows'

# this could change in the future, let's leave it isolated. - links = self._get_links(os, lc) + self.log.debug("Trying to get the links...") + try: + links = self._get_links(os, lc) + self.log.debug("OK") + except InternalError as e: + self.log.debug("FAILED") + raise InternalError("%s" % str(e))

if links is None: - raise InternalError("Something went wrong internally") + self.log.debug("No links found") + raise InternalError("No links. Something is wrong.")

- # thanks for stopping by return links

def _get_links(self, osys, lc): @@ -230,43 +219,45 @@ class Core(object): for name in links: # we're reading files listed on linksdir, so they must exist! config = ConfigParser.ConfigParser() - config.read(name) + # but just in case they don't + try: + with open(name) as f: + config.readfp(f) + except IOError: + raise InternalError("File %s not found!" % name)

try: pname = config.get('provider', 'name') - except ConfigParser.Error as e: - raise InternalError("Couldn't get 'name' from 'provider'")

- # checking if current provider pname has links for os in lc - try: + # check if current provider pname has links for os in lc providers[pname] = config.get(osys, lc) # avoid showing it all together providers[pname] = providers[pname].replace(",", "") providers[pname] = providers[pname].replace("$", "\n\n") - except ConfigParser.Error as e: - raise InternalError("Couldn't get %s from %s (%s)" % - (lc, osys, name))

- # all packages are signed with the same key (Tor Browser developers) - try: + # all packages are signed with same key + # (Tor Browser developers) fingerprint = config.get('key', 'fingerprint') fingerprint_msg = self._get_msg('fingerprint', lc) fingerprint_msg = fingerprint_msg % fingerprint except ConfigParser.Error as e: - raise InternalError("Couldn't get 'fingerprint' from 'key'") + raise InternalError("%s" % str(e))

# create the final links list with all providers all_links = []

for key in providers.keys(): # get more friendly description of the provider - provider_desc = self._get_msg('provider_desc', lc) - provider_desc = provider_desc % key + try: + provider_desc = self._get_msg('provider_desc', lc) + provider_desc = provider_desc % key

- all_links.append( - "%s\n%s\n\n%s%s\n\n\n" % - (provider_desc, spt, ''.join(providers[key]), spt) - ) + all_links.append( + "%s\n%s\n\n%s%s\n\n\n" % + (provider_desc, spt, ''.join(providers[key]), spt) + ) + except ConfigError as e: + raise InternalError("%s" % str(e))

# add fingerprint after the links all_links.append(fingerprint_msg) @@ -310,27 +301,41 @@ class Core(object): linksfile = os.path.join(self.linksdir, provider.lower() + '.links') linksfile_backup = ""

+ self.log.debug("Request to create a new links file") if os.path.isfile(linksfile): - # backup the old file in case something fails - linksfile_backup = linksfile + '.backup' - os.rename(linksfile, linksfile_backup) - - try: - # this creates an empty links file - content = ConfigParser.RawConfigParser() - content.add_section('provider') - content.set('provider', 'name', provider) - content.add_section('key') - content.set('key', 'fingerprint', fingerprint) - content.add_section('linux') - content.add_section('windows') - content.add_section('osx') - with open(linksfile, 'w+') as f: - content.write(f) - except Exception as e: - if linksfile_backup: - os.rename(linksfile_backup, linksfile) - raise LinkFileError("Error while creating new links file: %s" % e) + self.log.debug("Trying to backup the old one...") + try: + # backup the old file in case something fails + linksfile_backup = linksfile + '.backup' + os.rename(linksfile, linksfile_backup) + except OSError as e: + self.log.debug("FAILED %s" % str(e)) + raise LinkFileError( + "Error while creating new links file: %s" % str(e) + ) + + self.log.debug("Creating empty links file...") + try: + # this creates an empty links file + content = ConfigParser.RawConfigParser() + content.add_section('provider') + content.set('provider', 'name', provider) + content.add_section('key') + content.set('key', 'fingerprint', fingerprint) + content.add_section('linux') + content.add_section('windows') + content.add_section('osx') + with open(linksfile, 'w+') as f: + content.write(f) + except Exception as e: + self.log.debug("FAILED: %s" % str(e)) + # if we passed the last exception, then this shouldn't + # be a problem... + if linksfile_backup: + os.rename(linksfile_backup, linksfile) + raise LinkFileError( + "Error while creating new links file: %s" % str(e) + )

def add_link(self, provider, osys, lc, link): """Public method to add a link to a provider's links file. @@ -344,8 +349,7 @@ class Core(object): :param: lc (string) the locale. :param: link (string) link to be added.

- :raise: UnsupportedOSError if the operating system is not supported. - :raise: UnsupportedLocaleError if the locale is not supported. + :raise: NotsupportedError if the OS and/or locale is not supported. :raise: LinkFileError if there is no links file for the provider. :raise: LinkFormatError if the link format doesn't seem legit. :raise: InternalError if the links file doesn't have a section for @@ -355,33 +359,54 @@ class Core(object): """ linksfile = os.path.join(self.linksdir, provider.lower() + '.links')

+ self.log.debug("Request to add a new link") # don't try to add unsupported stuff if lc not in self.supported_lc: - raise UnsupportedLocaleError("Locale %s not supported" % lc) + self.log.debug("Request for locale %s not supported" % lc) + raise NotSupportedError("Locale %s not supported" % lc)

if osys not in self.supported_os: - raise UnsupportedOSError("OS %s not supported" % osys) + self.log.debug("Request for OS %s not supported" % osys) + raise NotSupportedError("OS %s not supported" % osys)

+ self.log.debug("Opening links file...") if os.path.isfile(linksfile): content = ConfigParser.RawConfigParser() - content.readfp(open(linksfile)) + + try: + with open(linksfile) as f: + content.readfp(f) + except IOError as e: + self.log.debug("FAILED %s" % str(e)) + raise LinksFileError("File %s not found!" % linksfile) # check if exists and entry for locale; if not, create it + self.log.debug("Trying to add the link...") try: links = content.get(osys, lc) links = "%s,\n%s" % (links, link) content.set(osys, lc, links) + self.log.debug("Link added") with open(linksfile, 'w') as f: content.write(f) except ConfigParser.NoOptionError: content.set(osys, lc, link) + self.log.debug("Link added (with new locale created)") with open(linksfile, 'w') as f: content.write(f) - except ConfigParser.NoSectionError: + except ConfigParser.NoSectionError as e: # this shouldn't happen, but just in case - raise InternalError("Unknown %s section in links file" % osys) + self.log.debug("FAILED (OS not found)") + raise InternalError("Unknown section %s" % str(e)) else: - raise LinkFileError("There is no links file for %s" % provider) + self.log.debug("FAILED (links file doesn't seem legit)") + raise LinkFileError("No links file for %s" % provider)

def add_request_to_db(self): """Add request to database.""" - self.db.add_request() + self.log.debug("Trying to add request to database") + try: + self.db.add_request() + self.log.debug("Request added!") + except db.DBError as e: + self.log.debug("FAILED %s" % str(e)) + raise InternalError("Couldn't add request to database %s" % str(e)) diff --git a/gettor/db.py b/gettor/db.py index e5e0acc..0b971af 100644 --- a/gettor/db.py +++ b/gettor/db.py @@ -17,6 +17,10 @@ import datetime """DB interface for comunicating with sqlite3"""

+class DBError(Exception): + pass + + class DB(object): """

@@ -27,6 +31,11 @@ class DB(object): add_user(): add a user to the database (users table). update_user(): update a user on the database (users table).

+ Exceptions: + + DBError: Something went wrong when trying to connect/interact + with the database. + """

def __init__(self, dbname): @@ -35,8 +44,11 @@ class DB(object): :param: dbname (string) the path of the database.

""" - self.con = sqlite3.connect(dbname) - self.con.row_factory = sqlite3.Row + try: + self.con = sqlite3.connect(dbname) + self.con.row_factory = sqlite3.Row + except sqlite3.Error as e: + raise DBError("%s" % str(e))

def add_request(self): """Add a request to the database. @@ -44,15 +56,18 @@ class DB(object): For now we just count the number of requests we have received so far.

""" - with self.con: - cur = self.con.cursor() - cur.execute("SELECT counter FROM requests WHERE id = 1") - row = cur.fetchone() - if row: - cur.execute("UPDATE requests SET counter=? WHERE id=?", - (row['counter']+1, 1)) - else: - cur.execute("INSERT INTO requests VALUES(?, ?)", (1, 1)) + try: + with self.con: + cur = self.con.cursor() + cur.execute("SELECT counter FROM requests WHERE id = 1") + row = cur.fetchone() + if row: + cur.execute("UPDATE requests SET counter=? WHERE id=?", + (row['counter']+1, 1)) + else: + cur.execute("INSERT INTO requests VALUES(?, ?)", (1, 1)) + except sqlite3.Error as e: + raise DBError("%s" % str(e))

def get_user(self, user, service): """Get user info from the database. @@ -64,13 +79,16 @@ class DB(object): (e.g. row['user']).

""" - with self.con: - cur = self.con.cursor() - cur.execute("SELECT * FROM users WHERE id =? AND service =?", - (user, service)) + try: + with self.con: + cur = self.con.cursor() + cur.execute("SELECT * FROM users WHERE id =? AND service =?", + (user, service))

- row = cur.fetchone() - return row + row = cur.fetchone() + return row + except sqlite3.Error as e: + raise DBError("%s" % str(e))

def add_user(self, user, service, blocked): """Add a user to the database. @@ -83,10 +101,13 @@ class DB(object): :param: blocked (int) one if user is blocked, zero otherwise.

""" - with self.con: - cur = self.con.cursor() - cur.execute("INSERT INTO users VALUES(?,?,?,?,?)", - (user, service, 1, blocked, str(time.time()))) + try: + with self.con: + cur = self.con.cursor() + cur.execute("INSERT INTO users VALUES(?,?,?,?,?)", + (user, service, 1, blocked, str(time.time()))) + except sqlite3.Error as e: + raise DBError("%s" % str(e))

def update_user(self, user, service, times, blocked): """Update a user on the database. @@ -99,8 +120,11 @@ class DB(object): :param: blocked (int) one if user is blocked, zero otherwise.

""" - with self.con: - cur = self.con.cursor() - cur.execute("UPDATE users SET times =?, blocked =?," - " last_request =? WHERE id =? AND service =?", - (times, blocked, str(time.time()), user, service)) + try: + with self.con: + cur = self.con.cursor() + cur.execute("UPDATE users SET times =?, blocked =?," + " last_request =? WHERE id =? AND service =?", + (times, blocked, str(time.time()), user, service)) + except sqlite3.Error as e: + raise DBError("%s" % str(e)) diff --git a/gettor/utils.py b/gettor/utils.py index cbf01ce..b4ab9c6 100644 --- a/gettor/utils.py +++ b/gettor/utils.py @@ -16,6 +16,25 @@ import hashlib """Common utilities for GetTor modules."""

+LOGGING_FORMAT = "[%(levelname)s] %(asctime)s - %(message)s" +DATE_FORMAT = "%Y-%m-%d" # %H:%M:%S + +def get_logging_format(): + """Get the logging format. + + :return: (string) the logging format. + + """ + return LOGGING_FORMAT + +def get_date_format(): + """Get the date format for logging. + + :return: (string) the date format for logging. + + """ + return DATE_FORMAT + def get_sha256(string): """Get sha256 of a string.