tobias/docker-offlineimap
1
0
Fork 0
Code Issues Pull Requests Packages Projects Releases Wiki Activity

Rework UI system to make use of the logging module

Browse Source 
Logging was flawed as the output was e.g. heavily buffered and people
complained about missing log entries. Fix this by making use of the
standard logging facilities that offlineimap offers.

This is one big ugly patch that does many things. It fixes the
Blinkenlights backend to work again with the logging facilities.

Resize windows and hotkeys are still not handled absolut correctly, this
is left for future fixing. THe rest of the backends should be working fine.

Signed-off-by: Sebastian Spaeth <Sebastian@SSpaeth.de>
This commit is contained in:
Sebastian Spaeth
2011-10-26 16:47:21 +02:00
parent d4a11c62ea
commit cbec8bb5b2
12 changed files with 829 additions and 945 deletions
Download Patch File Download Diff File Expand all files Collapse all files

358
offlineimap/ui/UIBase.py
View File

@ -15,12 +15,15 @@
# along with this program; if not, write to the Free Software
# Foundation, Inc., 51 Franklin St, Fifth Floor, Boston, MA 02110-1301 USA
import logging
import re
import time
import sys
import os
import traceback
import threading
from Queue import Queue
from collections import deque
import offlineimap
debugtypes = {'':'Other offlineimap related sync messages',
@ -38,54 +41,72 @@ def getglobalui():
global globalui
return globalui
class UIBase:
def __init__(s, config, verbose = 0):
s.verbose = verbose
s.config = config
s.debuglist = []
s.debugmessages = {}
s.debugmsglen = 50
s.threadaccounts = {}
class UIBase(object):
def __init__(self, config, loglevel = logging.INFO):
self.config = config
self.debuglist = []
"""list of debugtypes we are supposed to log"""
self.debugmessages = {}
"""debugmessages in a deque(v) per thread(k)"""
self.debugmsglen = 50
self.threadaccounts = {}
"""dict linking active threads (k) to account names (v)"""
s.acct_startimes = {}
self.acct_startimes = {}
"""linking active accounts with the time.time() when sync started"""
s.logfile = None
s.exc_queue = Queue()
self.logfile = None
self.exc_queue = Queue()
"""saves all occuring exceptions, so we can output them at the end"""
# create logger with 'OfflineImap' app
self.logger = logging.getLogger('OfflineImap')
self.logger.setLevel(loglevel)
self._log_con_handler = self.setup_consolehandler()
"""The console handler (we need access to be able to lock it)"""
################################################## UTILS
def _msg(s, msg):
"""Generic tool called when no other works."""
s._log(msg)
s._display(msg)
def setup_consolehandler(self):
"""Backend specific console handler
def _log(s, msg):
"""Log it to disk. Returns true if it wrote something; false
otherwise."""
if s.logfile:
s.logfile.write("%s: %s\n" % (threading.currentThread().getName(),
msg))
return 1
return 0
Sets up things and adds them to self.logger.
:returns: The logging.Handler() for console output"""
# create console handler with a higher log level
ch = logging.StreamHandler()
#ch.setLevel(logging.DEBUG)
# create formatter and add it to the handlers
self.formatter = logging.Formatter("%(message)s")
ch.setFormatter(self.formatter)
# add the handlers to the logger
self.logger.addHandler(ch)
self.logger.info(offlineimap.banner)
return ch
def setlogfd(s, logfd):
s.logfile = logfd
logfd.write("This is %s %s\n" % \
(offlineimap.__productname__,
offlineimap.__version__))
logfd.write("Python: %s\n" % sys.version)
logfd.write("Platform: %s\n" % sys.platform)
logfd.write("Args: %s\n" % sys.argv)
def setlogfile(self, logfile):
"""Create file handler which logs to file"""
fh = logging.FileHandler(logfile, 'wt')
#fh.setLevel(logging.DEBUG)
file_formatter = logging.Formatter("%(asctime)s %(levelname)s: "
"%(message)s", '%Y-%m-%d %H:%M:%S')
fh.setFormatter(file_formatter)
self.logger.addHandler(fh)
# write out more verbose initial info blurb on the log file
p_ver = ".".join([str(x) for x in sys.version_info[0:3]])
msg = "OfflineImap %s starting...\n Python: %s Platform: %s\n "\
"Args: %s" % (offlineimap.__version__, p_ver, sys.platform,
" ".join(sys.argv))
record = logging.LogRecord('OfflineImap', logging.INFO, __file__,
None, msg, None, None)
fh.emit(record)
def _display(s, msg):
def _msg(self, msg):
"""Display a message."""
raise NotImplementedError
# TODO: legacy function, rip out.
self.info(msg)
def warn(s, msg, minor = 0):
if minor:
s._msg("warning: " + msg)
else:
s._msg("WARNING: " + msg)
def info(self, msg):
"""Display a message."""
self.logger.info(msg)
def warn(self, msg, minor = 0):
self.logger.warning(msg)
def error(self, exc, exc_traceback=None, msg=None):
"""Log a message at severity level ERROR
@ -146,40 +167,43 @@ class UIBase:
return self.threadaccounts[thr]
return '*Control' # unregistered thread is '*Control'
def debug(s, debugtype, msg):
thisthread = threading.currentThread()
if s.debugmessages.has_key(thisthread):
s.debugmessages[thisthread].append("%s: %s" % (debugtype, msg))
else:
s.debugmessages[thisthread] = ["%s: %s" % (debugtype, msg)]
def debug(self, debugtype, msg):
cur_thread = threading.currentThread()
if not self.debugmessages.has_key(cur_thread):
# deque(..., self.debugmsglen) would be handy but was
# introduced in p2.6 only, so we'll need to work around and
# shorten our debugmsg list manually :-(
self.debugmessages[cur_thread] = deque()
self.debugmessages[cur_thread].append("%s: %s" % (debugtype, msg))
while len(s.debugmessages[thisthread]) > s.debugmsglen:
s.debugmessages[thisthread] = s.debugmessages[thisthread][1:]
# Shorten queue if needed
if len(self.debugmessages[cur_thread]) > self.debugmsglen:
self.debugmessages[cur_thread].popleft()
if debugtype in s.debuglist:
if not s._log("DEBUG[%s]: %s" % (debugtype, msg)):
s._display("DEBUG[%s]: %s" % (debugtype, msg))
if debugtype in self.debuglist: # log if we are supposed to do so
self.logger.debug("[%s]: %s" % (debugtype, msg))
def add_debug(s, debugtype):
def add_debug(self, debugtype):
global debugtypes
if debugtype in debugtypes:
if not debugtype in s.debuglist:
s.debuglist.append(debugtype)
s.debugging(debugtype)
if not debugtype in self.debuglist:
self.debuglist.append(debugtype)
self.debugging(debugtype)
else:
s.invaliddebug(debugtype)
self.invaliddebug(debugtype)
def debugging(s, debugtype):
def debugging(self, debugtype):
global debugtypes
s._msg("Now debugging for %s: %s" % (debugtype, debugtypes[debugtype]))
self.logger.debug("Now debugging for %s: %s" % (debugtype,
debugtypes[debugtype]))
def invaliddebug(s, debugtype):
s.warn("Invalid debug type: %s" % debugtype)
def invaliddebug(self, debugtype):
self.warn("Invalid debug type: %s" % debugtype)
def locked(s):
raise Exception, "Another OfflineIMAP is running with the same metadatadir; exiting."
def getnicename(s, object):
def getnicename(self, object):
"""Return the type of a repository or Folder as string
(IMAP, Gmail, Maildir, etc...)"""
@ -187,61 +211,73 @@ class UIBase:
# Strip off extra stuff.
return re.sub('(Folder|Repository)', '', prelimname)
def isusable(s):
def isusable(self):
"""Returns true if this UI object is usable in the current
environment. For instance, an X GUI would return true if it's
being run in X with a valid DISPLAY setting, and false otherwise."""
return 1
return True
################################################## INPUT
def getpass(s, accountname, config, errmsg = None):
raise NotImplementedError
def getpass(self, accountname, config, errmsg = None):
raise NotImplementedError("Prompting for a password is not supported"\
" in this UI backend.")
def folderlist(s, list):
return ', '.join(["%s[%s]" % (s.getnicename(x), x.getname()) for x in list])
def folderlist(self, list):
return ', '.join(["%s[%s]" % \
(self.getnicename(x), x.getname()) for x in list])
################################################## WARNINGS
def msgtoreadonly(s, destfolder, uid, content, flags):
if not (s.config.has_option('general', 'ignore-readonly') and s.config.getboolean("general", "ignore-readonly")):
s.warn("Attempted to synchronize message %d to folder %s[%s], but that folder is read-only. The message will not be copied to that folder." % \
(uid, s.getnicename(destfolder), destfolder.getname()))
def msgtoreadonly(self, destfolder, uid, content, flags):
if self.config.has_option('general', 'ignore-readonly') and \
self.config.getboolean('general', 'ignore-readonly'):
return
self.warn("Attempted to synchronize message %d to folder %s[%s], "
"but that folder is read-only. The message will not be "
"copied to that folder." % (
uid, self.getnicename(destfolder), destfolder))
def flagstoreadonly(s, destfolder, uidlist, flags):
if not (s.config.has_option('general', 'ignore-readonly') and s.config.getboolean("general", "ignore-readonly")):
s.warn("Attempted to modify flags for messages %s in folder %s[%s], but that folder is read-only. No flags have been modified for that message." % \
(str(uidlist), s.getnicename(destfolder), destfolder.getname()))
def flagstoreadonly(self, destfolder, uidlist, flags):
if self.config.has_option('general', 'ignore-readonly') and \
self.config.getboolean('general', 'ignore-readonly'):
return
self.warn("Attempted to modify flags for messages %s in folder %s[%s], "
"but that folder is read-only. No flags have been modified "
"for that message." % (
str(uidlist), self.getnicename(destfolder), destfolder))
def deletereadonly(s, destfolder, uidlist):
if not (s.config.has_option('general', 'ignore-readonly') and s.config.getboolean("general", "ignore-readonly")):
s.warn("Attempted to delete messages %s in folder %s[%s], but that folder is read-only. No messages have been deleted in that folder." % \
(str(uidlist), s.getnicename(destfolder), destfolder.getname()))
def deletereadonly(self, destfolder, uidlist):
if self.config.has_option('general', 'ignore-readonly') and \
self.config.getboolean('general', 'ignore-readonly'):
return
self.warn("Attempted to delete messages %s in folder %s[%s], but that "
"folder is read-only. No messages have been deleted in that "
"folder." % (str(uidlist), self.getnicename(destfolder),
destfolder))
################################################## MESSAGES
def init_banner(s):
def init_banner(self):
"""Called when the UI starts. Must be called before any other UI
call except isusable(). Displays the copyright banner. This is
where the UI should do its setup -- TK, for instance, would
create the application window here."""
if s.verbose >= 0:
s._msg(offlineimap.banner)
pass
def connecting(s, hostname, port):
def connecting(self, hostname, port):
"""Log 'Establishing connection to'"""
if s.verbose < 0: return
if not self.logger.isEnabledFor(logging.info): return
displaystr = ''
hostname = hostname if hostname else ''
port = "%s" % port if port else ''
if hostname:
displaystr = ' to %s:%s' % (hostname, port)
s._msg("Establishing connection%s" % displaystr)
self.logger.info("Establishing connection%s" % displaystr)
def acct(self, account):
"""Output that we start syncing an account (and start counting)"""
self.acct_startimes[account] = time.time()
if self.verbose >= 0:
self._msg("*** Processing account %s" % account)
self.logger.info("*** Processing account %s" % account)
def acctdone(self, account):
"""Output that we finished syncing an account (in which time)"""
@ -252,75 +288,63 @@ class UIBase:
def syncfolders(self, src_repo, dst_repo):
"""Log 'Copying folder structure...'"""
if self.verbose < 0: return
self.debug('', "Copying folder structure from %s to %s" % \
(src_repo, dst_repo))
if self.logger.isEnabledFor(logging.DEBUG):
self.debug('', "Copying folder structure from %s to %s" %\
(src_repo, dst_repo))
############################## Folder syncing
def syncingfolder(s, srcrepos, srcfolder, destrepos, destfolder):
def syncingfolder(self, srcrepos, srcfolder, destrepos, destfolder):
"""Called when a folder sync operation is started."""
if s.verbose >= 0:
s._msg("Syncing %s: %s -> %s" % (srcfolder.getname(),
s.getnicename(srcrepos),
s.getnicename(destrepos)))
self.logger.info("Syncing %s: %s -> %s" % (srcfolder,
self.getnicename(srcrepos),
self.getnicename(destrepos)))
def skippingfolder(s, folder):
def skippingfolder(self, folder):
"""Called when a folder sync operation is started."""
if s.verbose >= 0:
s._msg("Skipping %s (not changed)" % folder.getname())
self.logger.info("Skipping %s (not changed)" % folder)
def validityproblem(s, folder):
s.warn("UID validity problem for folder %s (repo %s) (saved %d; got %d); skipping it" % \
(folder.getname(), folder.getrepository().getname(),
def validityproblem(self, folder):
self.logger.warning("UID validity problem for folder %s (repo %s) "
"(saved %d; got %d); skipping it. Please see FAQ "
"and manual how to handle this." % \
(folder, folder.getrepository(),
folder.getsaveduidvalidity(), folder.getuidvalidity()))
def loadmessagelist(s, repos, folder):
if s.verbose > 0:
s._msg("Loading message list for %s[%s]" % (s.getnicename(repos),
folder.getname()))
def loadmessagelist(self, repos, folder):
self.logger.debug("Loading message list for %s[%s]" % (
self.getnicename(repos),
folder))
def messagelistloaded(s, repos, folder, count):
if s.verbose > 0:
s._msg("Message list for %s[%s] loaded: %d messages" % \
(s.getnicename(repos), folder.getname(), count))
def messagelistloaded(self, repos, folder, count):
self.logger.debug("Message list for %s[%s] loaded: %d messages" % (
self.getnicename(repos), folder, count))
############################## Message syncing
def syncingmessages(s, sr, sf, dr, df):
if s.verbose > 0:
s._msg("Syncing messages %s[%s] -> %s[%s]" % (s.getnicename(sr),
sf.getname(),
s.getnicename(dr),
df.getname()))
def syncingmessages(self, sr, srcfolder, dr, dstfolder):
self.logger.debug("Syncing messages %s[%s] -> %s[%s]" % (
self.getnicename(sr), srcfolder,
self.getnicename(dr), dstfolder))
def copyingmessage(self, uid, num, num_to_copy, src, destfolder):
"""Output a log line stating which message we copy"""
if self.verbose < 0: return
self._msg("Copy message %s (%d of %d) %s:%s -> %s" % (uid, num,
num_to_copy, src.repository, src, destfolder.repository))
self.logger.info("Copy message %s (%d of %d) %s:%s -> %s" % (
uid, num, num_to_copy, src.repository, src,
destfolder.repository))
def deletingmessage(s, uid, destlist):
if s.verbose >= 0:
ds = s.folderlist(destlist)
s._msg("Deleting message %d in %s" % (uid, ds))
def deletingmessages(self, uidlist, destlist):
ds = self.folderlist(destlist)
self.logger.info("Deleting %d messages (%s) in %s" % (
len(uidlist),
offlineimap.imaputil.uid_sequence(uidlist), ds))
def deletingmessages(s, uidlist, destlist):
if s.verbose >= 0:
ds = s.folderlist(destlist)
s._msg("Deleting %d messages (%s) in %s" % \
(len(uidlist),
offlineimap.imaputil.uid_sequence(uidlist),
ds))
def addingflags(self, uidlist, flags, dest):
self.logger.info("Adding flag %s to %d messages on %s" % (
", ".join(flags), len(uidlist), dest))
def addingflags(s, uidlist, flags, dest):
if s.verbose >= 0:
s._msg("Adding flag %s to %d messages on %s" % \
(", ".join(flags), len(uidlist), dest))
def deletingflags(s, uidlist, flags, dest):
if s.verbose >= 0:
s._msg("Deleting flag %s from %d messages on %s" % \
(", ".join(flags), len(uidlist), dest))
def deletingflags(self, uidlist, flags, dest):
self.logger.info("Deleting flag %s from %d messages on %s" % (
", ".join(flags), len(uidlist), dest))
def serverdiagnostics(self, repository, type):
"""Connect to repository and output useful information for debugging"""
@ -371,69 +395,68 @@ class UIBase:
################################################## Threads
def getThreadDebugLog(s, thread):
if s.debugmessages.has_key(thread):
def getThreadDebugLog(self, thread):
if self.debugmessages.has_key(thread):
message = "\nLast %d debug messages logged for %s prior to exception:\n"\
% (len(s.debugmessages[thread]), thread.getName())
message += "\n".join(s.debugmessages[thread])
% (len(self.debugmessages[thread]), thread.getName())
message += "\n".join(self.debugmessages[thread])
else:
message = "\nNo debug messages were logged for %s." % \
thread.getName()
return message
def delThreadDebugLog(s, thread):
if s.debugmessages.has_key(thread):
del s.debugmessages[thread]
def delThreadDebugLog(self, thread):
if thread in self.debugmessages:
del self.debugmessages[thread]
def getThreadExceptionString(s, thread):
def getThreadExceptionString(self, thread):
message = "Thread '%s' terminated with exception:\n%s" % \
(thread.getName(), thread.getExitStackTrace())
message += "\n" + s.getThreadDebugLog(thread)
message += "\n" + self.getThreadDebugLog(thread)
return message
def threadException(s, thread):
def threadException(self, thread):
"""Called when a thread has terminated with an exception.
The argument is the ExitNotifyThread that has so terminated."""
s._msg(s.getThreadExceptionString(thread))
s.delThreadDebugLog(thread)
s.terminate(100)
self.warn(self.getThreadExceptionString(thread))
self.delThreadDebugLog(thread)
self.terminate(100)
def terminate(self, exitstatus = 0, errortitle = None, errormsg = None):
"""Called to terminate the application."""
#print any exceptions that have occurred over the run
if not self.exc_queue.empty():
self._msg("\nERROR: Exceptions occurred during the run!")
self.warn("ERROR: Exceptions occurred during the run!")
while not self.exc_queue.empty():
msg, exc, exc_traceback = self.exc_queue.get()
if msg:
self._msg("ERROR: %s\n %s" % (msg, exc))
self.warn("ERROR: %s\n %s" % (msg, exc))
else:
self._msg("ERROR: %s" % (exc))
self.warn("ERROR: %s" % (exc))
if exc_traceback:
self._msg("\nTraceback:\n%s" %"".join(
self.warn("\nTraceback:\n%s" %"".join(
traceback.format_tb(exc_traceback)))
if errormsg and errortitle:
sys.stderr.write('ERROR: %s\n\n%s\n'%(errortitle, errormsg))
self.warn('ERROR: %s\n\n%s\n'%(errortitle, errormsg))
elif errormsg:
sys.stderr.write('%s\n' % errormsg)
self.warn('%s\n' % errormsg)
sys.exit(exitstatus)
def threadExited(s, thread):
def threadExited(self, thread):
"""Called when a thread has exited normally. Many UIs will
just ignore this."""
s.delThreadDebugLog(thread)
s.unregisterthread(thread)
self.delThreadDebugLog(thread)
self.unregisterthread(thread)
################################################## Hooks
def callhook(s, msg):
if s.verbose >= 0:
s._msg(msg)
def callhook(self, msg):
self.info(msg)
################################################## Other
def sleep(s, sleepsecs, account):
def sleep(self, sleepsecs, account):
"""This function does not actually output anything, but handles
the overall sleep, dealing with updates as necessary. It will,
however, call sleeping() which DOES output something.
@ -446,12 +469,12 @@ class UIBase:
if account.get_abort_event():
abortsleep = True
else:
abortsleep = s.sleeping(10, sleepsecs)
sleepsecs -= 10
s.sleeping(0, 0) # Done sleeping.
abortsleep = self.sleeping(10, sleepsecs)
sleepsecs -= 10
self.sleeping(0, 0) # Done sleeping.
return abortsleep
def sleeping(s, sleepsecs, remainingsecs):
def sleeping(self, sleepsecs, remainingsecs):
"""Sleep for sleepsecs, display remainingsecs to go.
Does nothing if sleepsecs <= 0.
@ -463,6 +486,7 @@ class UIBase:
"""
if sleepsecs > 0:
if remainingsecs//60 != (remainingsecs-sleepsecs)//60:
s._msg("Next refresh in %.1f minutes" % (remainingsecs/60.0))
self.logger.info("Next refresh in %.1f minutes" % (
remainingsecs/60.0))
time.sleep(sleepsecs)
return 0