Merge branch 'verbose_logging' into devel

10 files changed, 268 insertions, 35 deletions

diff --git a/jfr_playoff/data.py b/jfr_playoff/data.py
index a9c3a0c..d9eb314 100644
--- a/jfr_playoff/data.py
+++ b/jfr_playoff/data.py
@@ -4,13 +4,14 @@ from jfr_playoff.db import PlayoffDB
 from jfr_playoff.dto import Phase
 from jfr_playoff.matchinfo import MatchInfo
 from jfr_playoff.tournamentinfo import TournamentInfo
+from jfr_playoff.logger import PlayoffLogger
 
 
 class PlayoffData(object):
     def __init__(self, settings):
         self.database = PlayoffDB(settings.get('database')) if settings.has_section('database') else None
         if self.database is None:
-            print PlayoffDB.DATABASE_NOT_CONFIGURED_WARNING
+            PlayoffLogger.get('db').warning(PlayoffDB.DATABASE_NOT_CONFIGURED_WARNING)
         self.team_settings = settings.get('teams')
         self.phases = settings.get('phases')
         self.swiss = []
@@ -23,9 +24,14 @@ class PlayoffData(object):
     @cached_property
     def teams(self):
         if isinstance(self.team_settings, list):
+            PlayoffLogger.get('data').info(
+                'team list pre-defined: %s', self.team_settings)
             return self.team_settings
         tournament_info = TournamentInfo(self.team_settings, self.database)
-        return tournament_info.get_tournament_results()
+        team_list = tournament_info.get_tournament_results()
+        if len(team_list) == 0:
+            PlayoffLogger.get('data').warning('team list is empty!')
+        return team_list
 
     def generate_phases(self):
         self.grid = []
@@ -44,6 +50,7 @@ class PlayoffData(object):
                         phase_pos += 1
                 phase_object.matches[phase_pos] = match['id']
                 phase_pos += 1
+            PlayoffLogger.get('data').info('phase object: %s', phase_object)
             self.grid.append(phase_object)
         return self.grid
 
@@ -59,6 +66,8 @@ class PlayoffData(object):
                     for phase_obj in self.grid:
                         if match['id'] in phase_obj.matches:
                             phase_obj.running = True
+                PlayoffLogger.get('data').info(
+                    'match object: %s', self.match_info[match['id']])
         return self.match_info
 
     def get_swiss_link(self, event):
@@ -67,6 +76,7 @@ class PlayoffData(object):
         if ('relative_path' in event) and (
                 event['relative_path'] is not None):
             swiss_link = '%s/%s' % (event['relative_path'], swiss_link)
+        PlayoffLogger.get('data').info('swiss link: %s', swiss_link)
         return swiss_link
 
     def prefill_leaderboard(self, teams):
@@ -75,6 +85,7 @@ class PlayoffData(object):
             if len(team) > 3:
                 self.leaderboard[team[3]-1] = team[0]
         self.fill_swiss_leaderboard(self.swiss, teams)
+        PlayoffLogger.get('data').info('leaderboard pre-filled: %s', self.leaderboard)
         return self.leaderboard
 
     def fill_swiss_leaderboard(self, swiss, teams):
@@ -106,6 +117,8 @@ class PlayoffData(object):
                             self.leaderboard[
                                 target_position - 1] = team[0]
                     place += 1
+            PlayoffLogger.get('data').info(
+                'leaderboard after %s swiss: %s', event, self.leaderboard)
 
     def fill_leaderboard(self):
         self.prefill_leaderboard(self.teams)
@@ -126,30 +139,41 @@ class PlayoffData(object):
                         self.match_info[match['id']].loser)
         for positions, position_teams in leaderboard_teams.iteritems():
             positions = list(positions)
+            PlayoffLogger.get('data').info(
+                'filling leaderboard positions %s with teams %s',
+                positions, position_teams)
             if len(positions) == len([
                     team for team in position_teams if team is not None]):
                 for table_team in self.teams:
                     if table_team[0] in position_teams:
                         position = positions.pop(0)
                         self.leaderboard[position-1] = table_team[0]
+                        PlayoffLogger.get('data').info(
+                            'team %s in position %d', table_team[0], position)
+        PlayoffLogger.get('data').info(
+            'leaderboard filled: %s', self.leaderboard)
         return self.leaderboard
 
     def get_swiss_info(self):
-        return [{
+        swiss_info = [{
             'link': self.get_swiss_link(event),
             'position': event['position'],
             'label': event['label'] if 'label' in event else None,
             'finished': TournamentInfo(event, self.database).is_finished()
         } for event in self.swiss]
+        PlayoffLogger.get('data').info('swiss info: %s', swiss_info)
+        return swiss_info
 
     def get_dimensions(self):
-        return (
+        dimensions = (
             len(self.phases),
             max([
                 len(phase['matches']) + len(phase['dummies'])
                 if 'dummies' in phase
                 else len(phase['matches'])
                 for phase in self.phases]))
+        PlayoffLogger.get('data').info('grid dimensions: %s', dimensions)
+        return dimensions
 
     def get_shortname(self, fullname):
         for team in self.teams:
diff --git a/jfr_playoff/db.py b/jfr_playoff/db.py
index 71f3dcb..bca05d2 100644
--- a/jfr_playoff/db.py
+++ b/jfr_playoff/db.py
@@ -1,9 +1,12 @@
 import sys
 
+from jfr_playoff.logger import PlayoffLogger
+
+
 class PlayoffDB(object):
 
     db_cursor = None
-    DATABASE_NOT_CONFIGURED_WARNING = 'WARNING: database not configured'
+    DATABASE_NOT_CONFIGURED_WARNING = 'database not configured'
 
     def __init__(self, settings):
         reload(sys)
@@ -14,12 +17,14 @@ class PlayoffDB(object):
             password=settings['pass'],
             host=settings['host'],
             port=settings['port'])
+        PlayoffLogger.get('db').info('db settings: %s', settings)
         self.db_cursor = self.database.cursor(buffered=True)
 
     def get_cursor(self):
         return self.db_cursor
 
     def __execute_query(self, db_name, sql, params):
+        PlayoffLogger.get('db').info('query (%s): %s %s', db_name, sql.replace('\n', ' '), params)
         self.db_cursor.execute(sql.replace('#db#', db_name), params)
 
     def fetch(self, db_name, sql, params):
@@ -29,6 +34,7 @@ class PlayoffDB(object):
             row = self.db_cursor.fetchone()
             return row
         except mysql.connector.Error as e:
+            PlayoffLogger.get('db').error(str(e))
             raise IOError(e.errno, str(e), db_name)
 
     def fetch_all(self, db_name, sql, params):
@@ -38,6 +44,7 @@ class PlayoffDB(object):
             results = self.db_cursor.fetchall()
             return results
         except mysql.connector.Error as e:
+            PlayoffLogger.get('db').error(str(e))
             raise IOError(
                 message=str(e), filename=db_name,
                 errno=e.errno, strerror=str(e))
diff --git a/jfr_playoff/dto.py b/jfr_playoff/dto.py
index f5e08ef..a1b3a7f 100644
--- a/jfr_playoff/dto.py
+++ b/jfr_playoff/dto.py
@@ -1,7 +1,15 @@
+import sys
+
 class Team(object):
     name = ''
     score = 0.0
 
+    def __unicode__(self):
+        return u'%s (%.1f)' % (self.name, self.score)
+
+    def __repr__(self):
+        return unicode(self).encode(sys.stdin.encoding)
+
 
 class Match(object):
     id = None
@@ -13,6 +21,13 @@ class Match(object):
     winner_matches = None
     loser_matches = None
 
+    def __repr__(self):
+        return (u'#%d (%s) %s [%s]' % (
+            self.id, self.link, [unicode(team) for team in self.teams],
+            u'finished' if self.running < 0 else (
+                u'%d boards' % self.running))
+        ).encode(sys.stdin.encoding)
+
 
 class Phase(object):
     title = None
@@ -20,4 +35,9 @@ class Phase(object):
     matches = []
     running = False
 
+    def __repr__(self):
+        return u'%s (%s) <%d matches> [%srunning]' % (
+            self.title, self.link,
+            len(self.matches), '' if self.running else 'not ')
+
 __all__ = ('Team', 'Match', 'Phase')
diff --git a/jfr_playoff/filemanager.py b/jfr_playoff/filemanager.py
index 97f9cb8..515845e 100644
--- a/jfr_playoff/filemanager.py
+++ b/jfr_playoff/filemanager.py
@@ -2,6 +2,8 @@ import os
 import shutil
 import socket
 
+from jfr_playoff.logger import PlayoffLogger
+
 import __main__
 
 
@@ -9,12 +11,15 @@ class PlayoffFileManager(object):
 
     def __init__(self, settings):
         self.goniec = settings.get('goniec') if settings.has_section('goniec') else None
+        PlayoffLogger.get('filemanager').info('goniec settings: %s', self.goniec)
         self.output_file = settings.get('output')
+        PlayoffLogger.get('filemanager').info('output file: %s', self.output_file)
         self.output_path = os.path.dirname(
             self.output_file
         ).strip(os.sep)
         if len(self.output_path) > 0:
             self.output_path += os.sep
+        PlayoffLogger.get('filemanager').info('output path: %s', self.output_path)
         self.files = set()
 
     def reset(self):
@@ -22,14 +27,24 @@ class PlayoffFileManager(object):
 
     def register_file(self, path):
         if path.startswith(self.output_path):
+            PlayoffLogger.get('filemanager').info('registering file: %s', path)
             self.files.add(path.replace(self.output_path, ''))
+        else:
+            PlayoffLogger.get('filemanager').info(
+                'file: %s outside of %s, not registering', path, self.output_path)
 
     def write_content(self, content):
         output_dir = os.path.dirname(self.output_file)
         if len(output_dir) > 0:
             if not os.path.exists(output_dir):
+                PlayoffLogger.get('filemanager').info(
+                    'output directory %s does not exist, creating',
+                    output_dir)
                 os.makedirs(output_dir)
         output = open(self.output_file, 'w')
+        PlayoffLogger.get('filemanager').info(
+            'writing %d bytes into file %s',
+            len(content), self.output_file)
         output.write(content.encode('utf8'))
         output.close()
         self.register_file(self.output_file)
@@ -40,7 +55,12 @@ class PlayoffFileManager(object):
         script_output_dir = os.path.dirname(script_output_path)
         if len(script_output_dir) > 0:
             if not os.path.exists(script_output_dir):
+                PlayoffLogger.get('filemanager').info(
+                    'output directory %s does not exist, creating',
+                    script_output_dir)
                 os.makedirs(script_output_dir)
+        PlayoffLogger.get('filemanager').info(
+            'copying JS to %s', script_output_path)
         shutil.copy(
             unicode(os.path.join(
                 os.path.dirname(__main__.__file__), 'playoff.js')),
@@ -58,7 +78,8 @@ class PlayoffFileManager(object):
                 content_lines = [self.output_path] + \
                                 list(self.files) + \
                                 ['bye', '']
-                print '\n'.join(content_lines)
+                PlayoffLogger.get('goniec').info(
+                    '\n'.join(content_lines))
                 goniec = socket.socket()
                 goniec.connect((self.goniec['host'], self.goniec['port']))
                 goniec.sendall('\n'.join(content_lines))
diff --git a/jfr_playoff/generator.py b/jfr_playoff/generator.py
index cc4469d..97624a2 100644
--- a/jfr_playoff/generator.py
+++ b/jfr_playoff/generator.py
@@ -2,15 +2,20 @@ from datetime import datetime
 
 import jfr_playoff.template as p_temp
 from jfr_playoff.data import PlayoffData
+from jfr_playoff.logger import PlayoffLogger
 
 
 class PlayoffGenerator(object):
     def __init__(self, settings):
         self.data = PlayoffData(settings)
         self.page = settings.get('page')
+        PlayoffLogger.get('generator').info(
+            'page settings: %s', self.page)
         self.canvas = {}
         if settings.has_section('canvas'):
             self.canvas = settings.get('canvas')
+        PlayoffLogger.get('generator').info(
+            'canvas settings: %s', self.canvas)
 
     def generate_content(self):
         return p_temp.PAGE % (
@@ -55,6 +60,8 @@ class PlayoffGenerator(object):
         if match.running > 0:
             running_html = p_temp.MATCH_RUNNING % (match.running)
             html += p_temp.MATCH_LINK % (match.link, running_html) if match.link is not None else running_html
+        PlayoffLogger.get('generator').info(
+            'match table for #%d generated: %d bytes', match.id, len(html))
         return html
 
     def get_phase_header(self, phase, position):
@@ -95,6 +102,8 @@ class PlayoffGenerator(object):
             dimensions[1] * (
                 self.page['height'] + self.page['margin']
             ) - self.page['margin'])
+        PlayoffLogger.get('generator').info(
+            'canvas size: %s', canvas_size)
         grid_boxes = ''
         col_no = 0
         for phase in grid:
@@ -105,6 +114,9 @@ class PlayoffGenerator(object):
             for match in phase.matches:
                 grid_y = int(row_no * match_height +
                              0.5 * (match_height - self.page['height']))
+                PlayoffLogger.get('generator').info(
+                    'grid box (%d, %d) position: (%d, %d)',
+                    col_no, row_no, grid_x, grid_y)
                 grid_boxes += self.get_match_box(
                     matches[match] if match is not None else None,
                     (grid_x, grid_y))
@@ -130,6 +142,8 @@ class PlayoffGenerator(object):
                 position, self.get_flag(team), team or '')
             position += 1
         html = p_temp.LEADERBOARD.decode('utf8') % (rows)
+        PlayoffLogger.get('generator').info(
+            'leaderboard HTML generated: %d bytes', len(html))
         return html
 
     def get_swiss_links(self):
@@ -141,7 +155,10 @@ class PlayoffGenerator(object):
             info.append((p_temp.SWISS_LINK if event['finished'] else p_temp.SWISS_RUNNING_LINK) % (
                 event['link'], event_label
             ))
-        return '\n'.join(info)
+        html = '\n'.join(info)
+        PlayoffLogger.get('generator').info(
+            'swiss HTML generated: %d bytes', len(html))
+        return html
 
     def get_flag(self, team):
         flag = self.data.get_team_image(team)
diff --git a/jfr_playoff/matchinfo.py b/jfr_playoff/matchinfo.py
index 997e685..8132fe2 100644
--- a/jfr_playoff/matchinfo.py
+++ b/jfr_playoff/matchinfo.py
@@ -5,6 +5,7 @@ import jfr_playoff.sql as p_sql
 from jfr_playoff.dto import Match, Team
 from jfr_playoff.remote import RemoteUrl as p_remote
 from jfr_playoff.tournamentinfo import TournamentInfo
+from jfr_playoff.logger import PlayoffLogger
 
 class MatchInfo:
 
@@ -36,10 +37,15 @@ class MatchInfo:
     def __fetch_match_link(self):
         if 'link' in self.config:
             self.info.link = self.config['link']
+            PlayoffLogger.get('matchinfo').info(
+                'match #%d link pre-defined: %s', self.info.id, self.info.link)
         elif ('round' in self.config) and ('database' in self.config):
             event_info = TournamentInfo(self.config, self.database)
             self.info.link = event_info.get_results_link(
                 'runda%d.html' % (self.config['round']))
+            PlayoffLogger.get('matchinfo').info(
+                'match #%d link fetched: %s', self.info.id, self.info.link)
+        PlayoffLogger.get('matchinfo').info('match #%d link empty', self.info.id)
 
     def __get_predefined_scores(self):
         teams = [Team(), Team()]
@@ -62,6 +68,9 @@ class MatchInfo:
                 if i == 2:
                     break
             scores_fetched = True
+            PlayoffLogger.get('matchinfo').info(
+                'pre-defined scores for match #%d: %s',
+                self.info.id, teams)
         return scores_fetched, teams_fetched, teams
 
     def __get_db_teams(self, teams, fetch_scores):
@@ -77,6 +86,8 @@ class MatchInfo:
                 teams[0].score += row[2]
             else:
                 teams[1].score -= row[2]
+        PlayoffLogger.get('matchinfo').info(
+            'db scores for match #%d: %s', self.info.id, teams)
         return teams
 
     def __find_table_row(self, url):
@@ -84,7 +95,13 @@ class MatchInfo:
         for row in html_content.select('tr tr'):
             for cell in row.select('td.t1'):
                 if cell.text.strip() == str(self.config['table']):
+                    PlayoffLogger.get('matchinfo.html').debug(
+                        'HTML row for table %d found: %s',
+                        self.config['table'], row)
                     return row
+        PlayoffLogger.get('matchinfo.html').debug(
+            'HTML row for table %d not found',
+            self.config['table'])
         return None
 
     def __get_html_teams(self, teams, fetch_score):
@@ -104,6 +121,9 @@ class MatchInfo:
         for i in range(0, 2):
             teams[i].name = team_names[i]
             teams[i].score = scores[i]
+        PlayoffLogger.get('matchinfo').info(
+            'HTML scores for match #%d: %s',
+            self.info.id, teams)
         return teams
 
     def __get_config_teams(self, teams):
@@ -133,11 +153,16 @@ class MatchInfo:
                     else '??' for team in match_teams])
             else:
                 teams[i].name = ''
+        PlayoffLogger.get('matchinfo').info(
+            'config scores for match #%d: %s',
+            self.info.id, teams)
         return teams
 
     def __fetch_teams_with_scores(self):
         (scores_fetched, teams_fetched, self.info.teams) = self.__get_predefined_scores()
         if scores_fetched:
+            PlayoffLogger.get('matchinfo').info(
+                'pre-defined scores for match #%d fetched', self.info.id)
             if 'running' in self.config:
                 self.info.running = int(self.config['running'])
             else:
@@ -151,10 +176,16 @@ class MatchInfo:
                         raise KeyError('database not configured')
                     self.info.teams = self.__get_db_teams(
                         self.info.teams, not scores_fetched)
-                except (IOError, TypeError, IndexError, KeyError):
+                except (IOError, TypeError, IndexError, KeyError) as e:
+                    PlayoffLogger.get('matchinfo').warning(
+                        'fetching DB scores for match #%d failed: %s(%s)',
+                        self.info.id, type(e).__name__, str(e))
                     self.info.teams = self.__get_html_teams(
                         self.info.teams, not scores_fetched)
-            except (TypeError, IndexError, KeyError, IOError, ValueError):
+            except (TypeError, IndexError, KeyError, IOError, ValueError) as e:
+                PlayoffLogger.get('matchinfo').warning(
+                    'fetching HTML scores for match #%d failed: %s(%s)',
+                    self.info.id, type(e).__name__, str(e))
                 self.info.teams = self.__get_config_teams(self.info.teams)
 
     def __get_db_board_count(self):
@@ -170,6 +201,9 @@ class MatchInfo:
         boards_played = max(int(row[1]), 0)
         if boards_to_play > 0:
             boards_played += int(towels[0])
+        PlayoffLogger.get('matchinfo').info(
+            'DB board count for match #%d: %d/%d',
+            self.info.id, boards_played, boards_to_play)
         return boards_played, boards_to_play
 
     def __has_segment_link(self, cell):
@@ -196,8 +230,14 @@ class MatchInfo:
                 played_boards = len([
                     row for row in board_rows if len(
                         ''.join([cell.text.strip() for cell in row.select('td.bdc')])) > 0])
+                PlayoffLogger.get('matchinfo').info(
+                    'HTML played boards count for segment: %d/%d',
+                    played_boards, board_count)
                 return board_count, played_boards >= board_count
-            except IOError:
+            except IOError as e:
+                PlayoffLogger.get('matchinfo').info(
+                    'cannot fetch HTML played boards count for segment: %s(%s)',
+                    self.info.id, type(e).__name__, str(e))
                 return 0, False
         return 0, False
 
@@ -212,6 +252,8 @@ class MatchInfo:
         towels = [cell for cell in cells if self.__has_towel_image(cell)]
         if len(segments) == 0:
             if len(towels) > 0:
+                PlayoffLogger.get('matchinfo').info(
+                    'HTML board count for match #%d: all towels', self.info.id)
                 return 1, 1 # entire match is toweled, so mark as finished
             else:
                 raise ValueError('segments not found')
@@ -226,8 +268,14 @@ class MatchInfo:
                     finished_segments.append(segment)
                 if boards_in_segment is None and boards > 0:
                     boards_in_segment = boards
+        PlayoffLogger.get('matchinfo').info(
+            'HTML board count for match #%d, found: %d finished segments, %d towels, %d boards per segment and %d boards in running segment',
+            self.info.id, len(finished_segments), len(towels), boards_in_segment, running_boards)
         total_boards = (len(segments) + len(towels) + len(running_segments)) * boards_in_segment
         played_boards = (len(towels) + len(finished_segments)) * boards_in_segment + running_boards
+        PlayoffLogger.get('matchinfo').info(
+            'HTML board count for match #%d: %d/%d',
+            self.info.id, played_boards, total_boards)
         return played_boards, total_boards
 
     def __fetch_board_count(self):
@@ -237,10 +285,16 @@ class MatchInfo:
             if self.database is None:
                 raise KeyError('database not configured')
             boards_played, boards_to_play = self.__get_db_board_count()
-        except (IOError, TypeError, IndexError, KeyError):
+        except (IOError, TypeError, IndexError, KeyError) as e:
+            PlayoffLogger.get('matchinfo').warning(
+                'fetching board count from DB for match #%d failed: %s(%s)',
+                self.info.id, type(e).__name__, str(e))
             try:
                 boards_played, boards_to_play = self.__get_html_board_count()
-            except (TypeError, IndexError, KeyError, IOError, ValueError):
+            except (TypeError, IndexError, KeyError, IOError, ValueError) as e:
+                PlayoffLogger.get('matchinfo').warning(
+                    'fetching board count from HTML for match #%d failed: %s(%s)',
+                    self.info.id, type(e).__name__, str(e))
                 pass
         if boards_played > 0:
             self.info.running = -1 \
@@ -260,6 +314,9 @@ class MatchInfo:
         current_segment = int(
             self.database.fetch(
                 self.config['database'], p_sql.CURRENT_SEGMENT, ())[0])
+        PlayoffLogger.get('matchinfo').info(
+            'fetched running segment from DB for match #%d: %d',
+            self.info.id, current_segment)
         return '%s%st%d-%d.html' % (
             prefix, round_no, self.config['table'], current_segment)
 
@@ -270,6 +327,9 @@ class MatchInfo:
         running_link = row.select('td.bdcg a[href]')
         if len(running_link) == 0:
             raise ValueError('running link not found')
+        PlayoffLogger.get('matchinfo').info(
+            'fetched running link from HTML for match #%d: %s',
+            self.info.id, running_link)
         return urljoin(self.info.link, running_link[0]['href'])
 
     def __determine_running_link(self):
@@ -282,11 +342,16 @@ class MatchInfo:
                     raise KeyError('database not configured')
                 self.info.link = self.__get_db_running_link(
                     link_match.group(1), link_match.group(2))
-            except (IOError, TypeError, IndexError, KeyError):
+            except (IOError, TypeError, IndexError, KeyError) as e:
+                PlayoffLogger.get('matchinfo').warning(
+                    'cannot determine running link from DB for match #%d: %s(%s)',
+                    self.info.id, type(e).__name__, str(e))
                 try:
                     self.info.link = self.__get_html_running_link()
-                except (TypeError, IndexError, KeyError, IOError, ValueError):
-                    pass
+                except (TypeError, IndexError, KeyError, IOError, ValueError) as e:
+                    PlayoffLogger.get('matchinfo').warning(
+                        'cannot determine running link from HTML for match #%d: %s(%s)',
+                        self.info.id, type(e).__name__, str(e))
 
     def set_phase_link(self, phase_link):
         if self.info.link is None:
@@ -294,6 +359,9 @@ class MatchInfo:
         else:
             if self.info.link != '#':
                 self.info.link = urljoin(phase_link, self.info.link)
+        PlayoffLogger.get('matchinfo').info(
+            'applying phase link %s to match #%d: %s',
+            phase_link, self.info.id, self.info.link)
 
     def get_info(self):
         self.__fetch_teams_with_scores()
diff --git a/jfr_playoff/remote.py b/jfr_playoff/remote.py
index b687740..2deb7ce 100644
--- a/jfr_playoff/remote.py
+++ b/jfr_playoff/remote.py
@@ -3,6 +3,7 @@ import re
 import requests
 
 from bs4 import BeautifulSoup as bs
+from jfr_playoff.logger import PlayoffLogger
 
 class RemoteUrl:
 
@@ -10,6 +11,8 @@ class RemoteUrl:
 
     @classmethod
     def fetch(cls, url):
+        PlayoffLogger.get('remote').info(
+            'fetching content for: %s', url)
         if url not in cls.url_cache:
             request = requests.get(url)
             encoding_match = re.search(
diff --git a/jfr_playoff/settings.py b/jfr_playoff/settings.py
index 021253f..58de66c 100644
--- a/jfr_playoff/settings.py
+++ b/jfr_playoff/settings.py
@@ -4,6 +4,8 @@ import readline
 import requests
 import sys
 
+from jfr_playoff.logger import PlayoffLogger
+
 
 def complete_filename(text, state):
     return (glob.glob(text+'*')+[None])[state]
@@ -31,9 +33,9 @@ class PlayoffSettings(object):
                 if (key not in base_config) or overwrite:
                     base_config[key] = value
         except Exception as e:
-            print 'WARNING: unable to merge remote config: %s' % (str(e))
-            if remote_url is not None:
-                print 'Offending URL: %s' % (remote_url)
+            PlayoffLogger.get('settings').warning(
+                'unable to merge remote config %s: %s(%s)',
+                remote_url, type(e).__name__, str(e))
         return base_config
 
     def load(self):
@@ -45,16 +47,24 @@ class PlayoffSettings(object):
                 'JSON settings file: ').decode(sys.stdin.encoding)
 
         if self.settings is None:
+            PlayoffLogger.get('settings').info(
+                'loading config file: %s', unicode(self.settings_file))
             self.settings = json.loads(
                 open(unicode(self.settings_file)).read().decode('utf-8-sig'))
             if self.has_section('remotes'):
                 remote_config = {}
                 for remote in self.get('remotes'):
+                    PlayoffLogger.get('settings').info(
+                        'merging remote config: %s', remote)
                     remote_config = self.__merge_config(
                         remote_config, remote_url=remote)
+                    PlayoffLogger.get('settings').debug(
+                        'remote config: %s', remote_config)
                 self.settings = self.__merge_config(
                     self.settings, new_config=remote_config,
                     overwrite=False)
+            PlayoffLogger.get('settings').debug(
+                'parsed config: %s', self.settings)
 
     def has_section(self, key):
         self.load()
diff --git a/jfr_playoff/tournamentinfo.py b/jfr_playoff/tournamentinfo.py
index ee96214..a646d4e 100644
--- a/jfr_playoff/tournamentinfo.py
+++ b/jfr_playoff/tournamentinfo.py
@@ -3,8 +3,9 @@ import re
 
 import jfr_playoff.sql as p_sql
 from jfr_playoff.remote import RemoteUrl as p_remote
+from jfr_playoff.logger import PlayoffLogger
 
-SWISS_TIE_WARNING = 'WARNING: tie detected in swiss %s.' + \
+SWISS_TIE_WARNING = 'tie detected in swiss %s.' + \
                     ' Make sure to resolve the tie by arranging teams' + \
                     ' in configuration file.'
 
@@ -19,7 +20,9 @@ class TournamentInfo:
         if 'link' not in self.settings:
             raise KeyError('link not configured')
         if not self.settings['link'].endswith('leaderb.html'):
-            raise ValueError('unable to determine tournament results')
+            raise ValueError('invalid link to tournament results')
+        PlayoffLogger.get('tournamentinfo').info(
+            'fetching tournament results from leaderboard URL: %s', self.settings['link'])
         leaderboard = p_remote.fetch(self.settings['link'])
         result_links = [row.select('a[onmouseover]') for row in leaderboard.find_all('tr') if len(row.select('a[onmouseover]')) > 0]
         results = [None] * (len(result_links) * max([len(links) for links in result_links]))
@@ -39,15 +42,23 @@ class TournamentInfo:
                 if team_image is not None:
                     team_info.append(team_image['src'].replace('images/', ''))
                 teams.append(team_info)
+        PlayoffLogger.get('tournamentinfo').info(
+            'read tournament results from leaderboard: %s', teams)
         for table in range(1, int(ceil(len(teams)/2.0))+1):
             table_url = self.get_results_link('1t%d-1.html' % (table))
             table_content = p_remote.fetch(table_url)
+            PlayoffLogger.get('tournamentinfo').info(
+                'reading team shortnames from traveller: %s', table_url)
             for link in table_content.select('a.br'):
                 if link['href'] in team_links:
                     for team in teams:
                         if team[0] == team_links[link['href']]:
                             team[1] = link.text.strip(u'\xa0')
+                            PlayoffLogger.get('tournamentinfo').info(
+                                'shortname for %s: %s', team[0], team[1])
                             break
+        PlayoffLogger.get('tournamentinfo').info(
+            'tournament results from HTML: %s', teams)
         return teams
 
     def __get_db_results(self):
@@ -66,23 +77,44 @@ class TournamentInfo:
         swiss_results = sorted(
             swiss_results, key=lambda t: t[1], reverse=True)
         swiss_results = sorted(swiss_results, key=lambda team: team[2])
+        PlayoffLogger.get('tournamentinfo').info(
+            'fetched tournament results from database %s: %s',
+            self.settings['database'], swiss_results)
         prev_result = None
         for team in swiss_results:
             if prev_result == team[1]:
-                print SWISS_TIE_WARNING % (self.settings['database'])
+                PlayoffLogger.get('tournamentinfo').warning(
+                    SWISS_TIE_WARNING, self.settings['database'])
             prev_result = team[1]
         db_teams = [[team[0], team[3], team[4]] for team in swiss_results]
+        PlayoffLogger.get('tournamentinfo').info(
+            'fetched team list from database %s: %s',
+            self.settings['database'], db_teams)
         return db_teams
 
     def __get_html_finished(self):
         if 'link' not in self.settings:
             raise KeyError('link not configured')
         if not self.settings['link'].endswith('leaderb.html'):
-            raise ValueError('unable to determine tournament status')
+            raise ValueError('invalid tournament leaderboard link')
+        PlayoffLogger.get('tournamentinfo').info(
+            'fetching tournament finished status from HTML: %s',
+            self.settings['link'])
         leaderboard = p_remote.fetch(self.settings['link'])
         leaderb_heading = leaderboard.select('td.bdnl12')[0].text
+        contains_digits = any(char.isdigit() for char in leaderb_heading)
+        PlayoffLogger.get('tournamentinfo').info(
+            'tournament header from HTML: %s, %s',
+            leaderb_heading, 'contains digits' if contains_digits else "doesn't contain digits")
         non_zero_scores = [imps.text for imps in leaderboard.select('td.bdc small') if imps.text != '0-0']
-        return (not any(char.isdigit() for char in leaderb_heading)) and (len(non_zero_scores) > 0)
+        PlayoffLogger.get('tournamentinfo').info(
+            'tournament leaderboard from HTML: has %d non-zero scores',
+            len(non_zero_scores))
+        finished = (not contains_digits) and (len(non_zero_scores) > 0)
+        PlayoffLogger.get('tournamentinfo').info(
+            'tournament leaderboard from HTML indicates finished: %s',
+            finished)
+        return finished
 
     def __get_db_finished(self):
         if self.database is None:
@@ -91,14 +123,21 @@ class TournamentInfo:
             raise KeyError('database not configured')
         finished = self.database.fetch(
             self.settings['database'], p_sql.SWISS_ENDED, {})
+        PlayoffLogger.get('tournamentinfo').info(
+            'fetching tournament finished status from DB %s: %s',
+            self.settings['database'], finished)
         return (len(finished) > 0) and (finished[0] > 0)
 
     def __get_html_link(self, suffix='leaderb.html'):
         if 'link' not in self.settings:
             raise KeyError('link not configured')
         if not self.settings['link'].endswith('leaderb.html'):
-            raise ValueError('unable to determine html link')
-        return re.sub(r'leaderb.html$', suffix, self.settings['link'])
+            raise ValueError('invalid tournament leaderboard link')
+        link = re.sub(r'leaderb.html$', suffix, self.settings['link'])
+        PlayoffLogger.get('tournamentinfo').info(
+            'generating tournament-specific link from leaderboard link %s: %s -> %s',
+            self.settings['link'], suffix, link)
+        return link
 
     def __get_db_link(self, suffix='leaderb.html'):
         if self.database is None:
@@ -109,19 +148,31 @@ class TournamentInfo:
             self.settings['database'], p_sql.PREFIX, ())
         if row is not None:
             if len(row) > 0:
-                return row[0] + suffix
+                link = row[0] + suffix
+                PlayoffLogger.get('tournamentinfo').info(
+                    'generating tournament-specific link from DB %s prefix: %s -> %s',
+                    self.settings['database'], suffix, link)
+                return link
         raise ValueError('unable to fetch db link')
 
     def get_tournament_results(self):
         teams = []
         try:
             teams = self.__get_db_results()
-        except (IOError, TypeError, IndexError, KeyError):
+        except (IOError, TypeError, IndexError, KeyError) as e:
+            PlayoffLogger.get('tournamentinfo').warning(
+                'cannot determine tournament results from DB: %s(%s)',
+                type(e).__name__, str(e))
             try:
                 teams = self.__get_html_results()
-            except (TypeError, IndexError, KeyError, IOError, ValueError):
-                pass
+            except (TypeError, IndexError, KeyError, IOError, ValueError) as e:
+                PlayoffLogger.get('tournamentinfo').warning(
+                    'cannot determine tournament results from HTML: %s(%s)',
+                    type(e).__name__, str(e))
         if self.is_finished() and 'final_positions' in self.settings:
+            PlayoffLogger.get('tournamentinfo').info(
+                'setting final positions from tournament results: %s',
+                self.settings['final_positions'])
             for position in self.settings['final_positions']:
                 if len(teams) >= position:
                     teams[position-1].append(position)
@@ -130,19 +181,31 @@ class TournamentInfo:
     def is_finished(self):
         try:
             return self.__get_db_finished()
-        except (IOError, TypeError, IndexError, KeyError):
+        except (IOError, TypeError, IndexError, KeyError) as e:
+            PlayoffLogger.get('tournamentinfo').warning(
+                'cannot determine tournament finished status from DB: %s(%s)',
+                type(e).__name__, str(e))
             try:
                 return self.__get_html_finished()
-            except (TypeError, IndexError, KeyError, IOError, ValueError):
-                pass
+            except (TypeError, IndexError, KeyError, IOError, ValueError) as e:
+                PlayoffLogger.get('tournamentinfo').warning(
+                    'cannot determine tournament finished status from HTML: %s(%s)',
+                    type(e).__name__, str(e))
+        PlayoffLogger.get('tournamentinfo').info(
+            'assuming tournament is finished')
         return True
 
     def get_results_link(self, suffix='leaderb.html'):
         try:
             return self.__get_db_link(suffix)
-        except (IOError, TypeError, IndexError, KeyError):
+        except (IOError, TypeError, IndexError, KeyError) as e:
+            PlayoffLogger.get('tournamentinfo').warning(
+                'cannot determine tournament link from DB: %s(%s)',
+                type(e).__name__, str(e))
             try:
                 return self.__get_html_link(suffix)
             except (KeyError, ValueError):
-                pass
+                PlayoffLogger.get('tournamentinfo').warning(
+                    'cannot determine tournament link from HTML: %s(%s)',
+                    type(e).__name__, str(e))
         return None
diff --git a/playoff.py b/playoff.py
index 16113fc..ac84c66 100644
--- a/playoff.py
+++ b/playoff.py
@@ -30,7 +30,7 @@ def main():
             'INFO' if arguments.verbose else (
                 'DEBUG' if arguments.debug else 'WARNING')))
 
-        PlayoffLogger.get().debug('started with arguments: %s', arguments)
+        PlayoffLogger.get().info('started with arguments: %s', arguments)
 
         settings = PlayoffSettings(arguments.config_file)
         interactive = settings.interactive