new fancier log output

13 files changed, 114 insertions, 127 deletions

diff --git a/portato/__init__.py b/portato/__init__.py
index 4b1f42f..0166170 100644
--- a/portato/__init__.py
+++ b/portato/__init__.py
@@ -3,9 +3,55 @@
 # File: portato/__init__.py
 # This file is part of the Portato-Project, a graphical portage-frontend.
 #
-# Copyright (C) 2006 René 'Necoro' Neumann
+# Copyright (C) 2006-2007 René 'Necoro' Neumann
 # This is free software.  You may redistribute copies of it under the terms of
 # the GNU General Public License version 2.
 # There is NO WARRANTY, to the extent permitted by law.
 #
 # Written by René 'Necoro' Neumann <necoro@necoro.net>
+
+import logging
+import sys
+import os
+
+class OutputFormatter (logging.Formatter):
+
+	colors = { 
+			"blue"	: 34,
+			"green"	: 32,
+			"red"	: 31,
+			"yellow": 33
+			}
+
+	def __init__(self, *args, **kwargs):
+		logging.Formatter.__init__(self, *args, **kwargs)
+
+		for key, value in self.colors.iteritems():
+			self.colors[key] = "\x1b[01;%02dm*\x1b[39;49;00m" % value
+
+	def format (self, record):
+		string = logging.Formatter.format(self, record)
+		color = None
+
+		if os.isatty(sys.stderr.fileno()):
+			if record.levelno <= logging.DEBUG:
+				color = self.colors["blue"]
+			elif record.levelno <= logging.INFO:
+				color = self.colors["green"]
+			elif record.levelno <= logging.WARNING:
+				color = self.colors["yellow"]
+			else:
+				color = self.colors["red"]
+		else:
+			color = "%s:" % record.levelname
+
+		return "%s %s" % (color, string)
+
+# set the whole logging stuff
+formatter = OutputFormatter("%(message)s (%(filename)s:%(lineno)s)")
+
+handler = logging.StreamHandler()
+handler.setFormatter(formatter)
+logging.getLogger().addHandler(handler)
+
+logging.getLogger().setLevel(logging.DEBUG)
diff --git a/portato/backend/flags.py b/portato/backend/flags.py
index 9cd061a..6c2a159 100644
--- a/portato/backend/flags.py
+++ b/portato/backend/flags.py
@@ -217,7 +217,7 @@ def set_use_flag (pkg, flag):
 	if not cpv in newUseFlags:
 		newUseFlags[cpv] = []
 
-	debug("data: "+str(data))
+	debug("data: %s", str(data))
 	# add a useflag / delete one
 	added = False
 	for file, line, crit, flags in data:
@@ -256,7 +256,7 @@ def set_use_flag (pkg, flag):
 			newUseFlags[cpv].append((path, -1, flag, False))
 
 	newUseFlags[cpv] = unique_array(newUseFlags[cpv])
-	debug("newUseFlags: "+str(newUseFlags))
+	debug("newUseFlags: %s", str(newUseFlags))
 
 def remove_new_use_flags (cpv):
 	"""Removes all new use-flags for a specific package.
@@ -429,7 +429,7 @@ def set_masked (pkg, masked = True):
 		return
 
 	data = get_data(pkg, path)
-	debug("data:", str(data))
+	debug("data: %s", str(data))
 	done = False
 	for file, line, crit, flags in data:
 		if pkg.matches(crit):
@@ -452,7 +452,7 @@ def set_masked (pkg, masked = True):
 	
 	link_neq[cpv].append((file, "-1"))
 	link_neq[cpv] = unique_array(link_neq[cpv])
-	debug("new_(un)masked: "+str(link_neq))
+	debug("new_(un)masked: %s",str(link_neq))
 
 def remove_new_masked (cpv):
 	if isinstance(cpv, package.Package):
@@ -478,7 +478,7 @@ def new_masking_status (cpv):
 			for file, line in list[cpv]:
 				_ret = (int(line) == -1)
 				if ret is not None and _ret != ret:
-					debug("Conflicting values for masking status!", list, error = True)
+					error("Conflicting values for masking status: %s", list)
 				else:
 					ret = _ret
 		return ret
@@ -635,7 +635,7 @@ def set_testing (pkg, enable):
 
 	if not enable:
 		test = get_data(pkg, CONST.testing_path())
-		debug("data (test): "+str(test))
+		debug("data (test): %s", str(test))
 		for file, line, crit, flags in test:
 			if pkg.matches(crit) and flags[0] == "~"+arch:
 				newTesting[cpv].append((file, line))
@@ -647,7 +647,7 @@ def set_testing (pkg, enable):
 		newTesting[cpv].append((file, "-1"))
 
 	newTesting[cpv] = unique_array(newTesting[cpv])
-	debug("newTesting: "+str(newTesting))
+	debug("newTesting: %s",str(newTesting))
 
 def write_testing ():
 	global arch, newTesting
diff --git a/portato/backend/portage/package.py b/portato/backend/portage/package.py
index d819f2d..4f4b618 100644
--- a/portato/backend/portage/package.py
+++ b/portato/backend/portage/package.py
@@ -86,7 +86,7 @@ class PortagePackage (Package):
 				if status == "masked": return True
 				elif status == "unmasked": return False
 				else:
-					debug("BUG in flags.new_masking_status. It returns", status, error = True)
+					error("BUG in flags.new_masking_status. It returns \'%s\'", status)
 			else: # we have not touched the status
 				if self._status and ("profile" in self._status or "package.mask" in self._status):
 					return True
diff --git a/portato/backend/portage/system.py b/portato/backend/portage/system.py
index 739c577..92bdf51 100644
--- a/portato/backend/portage/system.py
+++ b/portato/backend/portage/system.py
@@ -16,7 +16,7 @@ import portage
 
 import package
 from settings import PortageSettings
-from portato.helper import debug, unique_array
+from portato.helper import *
 from portato.backend.system_interface import SystemInterface
 
 class PortageSystem (SystemInterface):
@@ -121,12 +121,14 @@ class PortageSystem (SystemInterface):
 
 	def find_best_match (self, search_key, only_installed = False):
 		t = None
+		
 		if not only_installed:
-			t = self.settings.porttree.dep_bestmatch(search_key)
+			t = self.find_packages(search_key)
 		else:
-			t = self.settings.vartree.dep_bestmatch(search_key)
+			t = self.find_installed_packages(search_key)
+
 		if t:
-			return package.PortagePackage(t)
+			return self.find_best([x.get_cpv() for x in t])
 		return None
 
 	def find_packages (self, search_key, masked=False):
@@ -277,7 +279,7 @@ class PortageSystem (SystemInterface):
 			
 			best_p = self.find_best_match(p)
 			if best_p is None:
-				debug("No best match for",p,"-- It seems not to be in the tree anymore.",warn = True)
+				warning("No best match for %s. It seems not to be in the tree anymore." % p)
 				continue
 
 			if len(inst) > 1:
@@ -334,7 +336,7 @@ class PortageSystem (SystemInterface):
 					oldList = self.sort_package_list(self.find_installed_packages(p.get_cp()))
 					if not oldList:
 						if add_not_installed:
-							debug("Not found installed",p.get_cpv(),"==> adding")
+							info("Found a not installed dependency: %s." % p.get_cpv())
 							oldList = [p]
 						else:
 							return
@@ -374,7 +376,7 @@ class PortageSystem (SystemInterface):
 							raw_checked.append(i)
 							bm = self.get_new_packages([i])
 							if not bm: 
-								debug("Bug? No best match could be found:",i)
+								warning("Bug? No best match could be found for %s.",i)
 							else:
 								for pkg in bm: 
 									if not pkg: continue
diff --git a/portato/config_parser.py b/portato/config_parser.py
index 19d3929..32e0518 100644
--- a/portato/config_parser.py
+++ b/portato/config_parser.py
@@ -207,7 +207,7 @@ class ConfigParser:
 				self.vars[section][key] = Value(val, count, bool = bool)
 				self.pos[count] = match.span(2)
 			else: # neither comment nor empty nor expression nor section => error
-				debug("Unrecognized line in configuration:", line, error = 1)
+				error("Unrecognized line in configuration: %s", line)
 
 	def get (self, key, section = "MAIN"):
 		"""Returns the value of a given key in a section.
diff --git a/portato/gui/gtk/windows.py b/portato/gui/gtk/windows.py
index 6eacd34..ac87b01 100644
--- a/portato/gui/gtk/windows.py
+++ b/portato/gui/gtk/windows.py
@@ -609,7 +609,6 @@ class PackageTable:
 					combo.set_active(i)
 					break
 		except AttributeError: # no package found
-#			debug('catched AttributeError => no "best package" found. Selected first one.')
 			combo.set_active(0)
 
 		combo.connect("changed", self.cb_combo_changed)
@@ -638,7 +637,7 @@ class PackageTable:
 			try:
 				self.queue.append(self.actual_package().get_cpv(), unmerge = True)
 			except PackageNotFoundException, e:
-				debug("Package could not be found",e[0], error = 1)
+				error("Package could not be found: %s", e[0])
 				#masked_dialog(e[0])
 
 	def cb_combo_changed (self, combo):
@@ -1105,9 +1104,9 @@ class MainWindow (Window):
 			flags.write_use_flags()
 		
 		if len(flags.new_masked)>0 or len(flags.new_unmasked)>0 or len(flags.newTesting)>0:
-			debug("new masked:",flags.new_masked)
-			debug("new unmasked:", flags.new_unmasked)
-			debug("new testing:", flags.newTesting)
+			debug("new masked: %s",flags.new_masked)
+			debug("new unmasked: %s", flags.new_unmasked)
+			debug("new testing: %s", flags.newTesting)
 			changed_flags_dialog("masking keywords")
 			flags.write_masked()
 			flags.write_testing()
@@ -1134,7 +1133,7 @@ class MainWindow (Window):
 		else:
 			updating = system.update_world(newuse = self.cfg.get_boolean("newuse"), deep = self.cfg.get_boolean("deep"))
 
-			debug("updating list:", [(x.get_cpv(), y.get_cpv()) for x,y in updating],"--> length:",len(updating))
+			debug("updating list: %s --> length: %s", [(x.get_cpv(), y.get_cpv()) for x,y in updating], len(updating))
 			try:
 				try:
 					for pkg, old_pkg in updating:
diff --git a/portato/gui/gui_helper.py b/portato/gui/gui_helper.py
index 8ee858f..f9dd3fe 100644
--- a/portato/gui/gui_helper.py
+++ b/portato/gui/gui_helper.py
@@ -29,6 +29,7 @@ import pty
 import time
 import os
 import signal
+import logging
 
 class Config:
 	"""Wrapper around a ConfigParser and for additional local configurations."""
@@ -103,9 +104,12 @@ class Config:
 		flags.set_config(flagCfg)
 
 	def modify_debug_config (self):
-		"""Sets the external debug-config.
-		@see: L{helper.set_debug()}"""
-		set_debug(self.get_boolean("debug"))
+		if self.get_boolean("debug"):
+			level = logging.DEBUG
+		else:
+			level = logging.INFO
+
+		set_log_level(level)
 
 	def modify_system_config (self):
 		"""Sets the system config.
@@ -232,7 +236,7 @@ class Database:
 				return inst+ninst
 
 		except KeyError: # cat is in category list - but not in portage
-			debug("Catched KeyError =>", cat, "seems not to be an available category. Have you played with rsync-excludes?")
+			info("Catched KeyError => %s seems not to be an available category. Have you played with rsync-excludes?", cat)
 			return []
 
 	def reload (self, cat):
@@ -378,7 +382,7 @@ class EmergeQueue:
 			try:
 				self.update_tree(subIt, d, unmask)
 			except backend.BlockedException, e: # BlockedException occured -> delete current tree and re-raise exception
-				debug("Something blocked:", e[0])
+				debug("Something blocked: %s", e[0])
 				self.remove_with_children(subIt)
 				raise
 		
@@ -470,7 +474,7 @@ class EmergeQueue:
 				if p in ["world", "system"]: continue
 				cat = system.split_cpv(p)[0] # get category
 				self.db.reload(cat)
-				debug("Category %s refreshed" % cat)
+				debug("Category %s refreshed", cat)
 
 		update_packages()
 		self.process = None
@@ -687,14 +691,14 @@ class EmergeQueue:
 				try:
 					del self.deps[cpv]
 				except KeyError: # this seems to be removed due to a BlockedException - so no deps here atm ;)
-					debug("Catched KeyError =>", cpv, "seems not to be in self.deps. Should be no harm in normal cases.")
+					debug("Catched KeyError => %s seems not to be in self.deps. Should be no harm in normal cases.", cpv)
 				try:
 					self.mergequeue.remove(cpv)
 				except ValueError: # this is a dependency - ignore
 					try:
 						self.oneshotmerge.remove(cpv)
 					except ValueError:
-						debug("Catched ValueError =>", cpv, "seems not to be in merge-queue. Should be no harm.")
+						debug("Catched ValueError => %s seems not to be in merge-queue. Should be no harm.", cpv)
 				
 				if removeNewFlags: # remove the changed flags
 					flags.remove_new_use_flags(cpv)
diff --git a/portato/gui/qt/terminal.py b/portato/gui/qt/terminal.py
index 0c7cf8b..a70e56b 100644
--- a/portato/gui/qt/terminal.py
+++ b/portato/gui/qt/terminal.py
@@ -17,16 +17,17 @@ from threading import Thread, currentThread
 from os import read, close
 import errno
 
+from portato.gui.wrapper import Console
+from portato.helper import debug
+
 try:
 	from curses.ascii import ctrl
 except ImportError: # emulate ctrl-behavior for known values
 	def ctrl (val):
 		if val == "H": return '\x08'
 		elif val == "W": return '\x17'
-		else: debug("unknown error passed to emulated ctrl:",val)
+		else: debug("unknown error passed to emulated ctrl: %s",val)
 
-from portato.gui.wrapper import Console
-from portato.helper import debug
 
 class WriteEvent (Qt.QEvent):
 	TYPE = Qt.QEvent.Type(1001)
diff --git a/portato/gui/qt/windows.py b/portato/gui/qt/windows.py
index a61a6d7..2f40dcf 100644
--- a/portato/gui/qt/windows.py
+++ b/portato/gui/qt/windows.py
@@ -497,7 +497,7 @@ class PackageDetails:
 			try:
 				self.queue.append(self.actual_package().get_cpv(), unmerge = True)
 			except PackageNotFoundException, e:
-				debug("Package could not be found",e[0], error = 1)
+				error("Package could not be found: %s", e[0])
 
 
 	def actual_package (self):
@@ -971,9 +971,9 @@ class MainWindow (Window):
 			flags.write_use_flags()
 		
 		if len(flags.new_masked)>0 or len(flags.new_unmasked)>0 or len(flags.newTesting)>0:
-			debug("new masked:",flags.new_masked)
-			debug("new unmasked:", flags.new_unmasked)
-			debug("new testing:", flags.newTesting)
+			debug("new masked: %s",flags.new_masked)
+			debug("new unmasked: %s", flags.new_unmasked)
+			debug("new testing: %s", flags.newTesting)
 			changed_flags_dialog(self, "masking keywords")
 			flags.write_masked()
 			flags.write_testing()
@@ -1001,7 +1001,7 @@ class MainWindow (Window):
 		else:
 			updating = system.update_world(newuse = self.cfg.get_boolean("newuse"), deep = self.cfg.get_boolean("deep"))
 
-			debug("updating list:", [(x.get_cpv(), y.get_cpv()) for x,y in updating],"--> length:",len(updating))
+			debug("updating list: %s --> length: %s", [(x.get_cpv(), y.get_cpv()) for x,y in updating], len(updating))
 			try:
 				try:
 					for pkg, old_pkg in updating:
diff --git a/portato/helper.py b/portato/helper.py
index cc797b9..f25fa34 100644
--- a/portato/helper.py
+++ b/portato/helper.py
@@ -12,74 +12,13 @@
 
 """
 Some nice functions used in the program.
-
-@var DEBUG: Boolean controlling whether to printout debug messages.
-@type DEBUG: boolean
 """
 
-import traceback, os.path, sys, types
-import os, signal
-
-DEBUG = True
-
-def set_debug (d):
-	"""Sets the global DEBUG variable. Do not set it by your own - always use this function.
-
-	@param d: True to enable debugging; False otherwise
-	@type d: boolean"""
-
-	global DEBUG
-	DEBUG = d
-
-def debug(*args, **kwargs):
-	"""Prints a debug message including filename and lineno.
-	A variable number of positional arguments are allowed.
-
-	If debug(obj0, obj1, obj2) is called, the text part of the output 
-	looks like the output from print obj0, obj1, obj2.
-	
-	@keyword name: Use the given name instead the correct function name.
-	@keyword file: Output file to use.
-	@keyword minus: The value given is the amount of frames to ignore in the stack to return the correct function call.
-	This should be used if you are wrapping the debug call.
-	@keyword warn: Prints the message as a warning. Value of DEBUG is ignored.
-	@keyword error: Prints the message as an error. Value of DEBUG is ignored."""
-
-	if not DEBUG and not ("warn" in kwargs or "error" in kwargs): return
-	
-	stack = traceback.extract_stack()
-	minus = -2
-	if "minus" in kwargs:
-		minus = minus - kwargs["minus"]
-	a, b, c, d = stack[minus]
-	a = os.path.basename(a)
-	out = []
-	for obj in args:
-		out.append(str(obj))
-	text = ' '.join(out)
-	if "name" in kwargs:
-		text = 'In %s (%s:%s): %s' % (kwargs["name"], a, b, text)
-	else:
-		text = 'In %s (%s:%s): %s' % (c, a, b, text)
-	
-	outfile = sys.stdout
-	surround = "DEBUG"
+import types, os, signal, logging
+from logging import debug, info, warning, error, critical, exception
 
-	if "warn" in kwargs:
-		outfile = sys.stderr
-		surround = "WARNING"
-	elif "error" in kwargs:
-		outfile = sys.stderr
-		surround = "ERROR"
-
-	text = ("***%s*** %s ***%s***" % (surround, text, surround))
-	
-	if "file" in kwargs:
-		f = open(kwargs["file"], "a+")
-		f.write(text+"\n")
-		f.close()
-	else:
-		print >> outfile, text
+def set_log_level (lvl):
+	logging.getLogger().setLevel(lvl)
 
 def send_signal_to_group (sig):
 	"""Sends a signal to all processes of our process group (w/o ourselves).
diff --git a/portato/plugin.py b/portato/plugin.py
index ebc1e2f..a833696 100644
--- a/portato/plugin.py
+++ b/portato/plugin.py
@@ -16,15 +16,11 @@ import os, os.path
 from xml.dom.minidom import parse
 
 from constants import PLUGIN_DIR
-from helper import debug, flatten
+from helper import *
 
 class ParseException (Exception):
 	pass
 
-def error (reason, p):
-	reason = "("+reason+")"
-	debug("Malformed plugin:", p, reason, minus=1, error = 1)
-
 class Options (object):
 	"""The <options>-element."""
 
@@ -343,18 +339,18 @@ class PluginQueue:
 				try:
 					mod = __import__(imp, globals(), locals(), [cmd.hook.call])
 				except ImportError:
-					debug(imp,"cannot be imported", error = 1)
+					error("%s cannot be imported.", imp)
 					return
 
 				try:
 					f = eval("mod."+cmd.hook.call) # build function
 				except AttributeError:
-					debug(cmd.hook.call,"cannot be imported", error = 1)
+					error("%s cannot be imported.", cmd.hook.call)
 			else:
 				try:
 					f = eval(cmd.hook.call)
 				except AttributeError:
-					debug(cmd.hook.call,"cannot be imported", error = 1)
+					error("%s cannot be imported", cmd.hook.call)
 
 			return f(*hargs, **hkwargs) # call function
 
@@ -381,18 +377,18 @@ class PluginQueue:
 
 				# before
 				for cmd in list[0]:
-					debug("Accessing hook '%s' of plugin '%s' (before)" % (hook, cmd.hook.plugin.name))
+					debug("Accessing hook '%s' of plugin '%s' (before).", hook, cmd.hook.plugin.name)
 					call(cmd)
 				
 				if list[1]: # override
-					debug("Overriding hook '%s' with plugin '%s'" % (hook, list[1][0].hook.plugin.name))
+					info("Overriding hook '%s' with plugin '%s'.", hook, list[1][0].hook.plugin.name)
 					ret = call(list[1][0])
 				else: # normal
 					ret = func(*args, **kwargs)
 
 				# after
 				for cmd in list[2]:
-					debug("Accessing hook '%s' of plugin '%s' (after)" % (hook, cmd.hook.plugin.name))
+					debug("Accessing hook '%s' of plugin '%s' (after).", hook, cmd.hook.plugin.name)
 					call(cmd)
 
 				return ret
@@ -413,7 +409,7 @@ class PluginQueue:
 				try:
 					list = doc.getElementsByTagName("plugin")
 					if len(list) != 1:
-						raise ParseException, "Number of plugin elements unequal to 1"
+						raise ParseException, "Number of plugin elements unequal to 1."
 					
 					elem = list[0]
 
@@ -444,7 +440,7 @@ class PluginQueue:
 						self.list.append(plugin)
 
 				except ParseException, e:
-					error(e[0],p)
+					error("Malformed plugin \"%s\". Reason: %s", p, e[0])
 			finally:
 				doc.unlink()
 
@@ -509,7 +505,7 @@ class PluginQueue:
 					# type = "override"
 					elif connect.is_override_type():
 						if self.hooks[hook.hook][1]:
-							debug("For hook '%s' an override is already defined by plugin '%s'!" % (hook.hook, self.hooks[hook.hook][1][0]), warn = 1)
+							warn("For hook '%s' an override is already defined by plugin '%s'!", hook.hook, self.hooks[hook.hook][1][0])
 						
 						self.hooks[hook.hook][1][:1] = [connect]
 						continue
@@ -540,7 +536,7 @@ class PluginQueue:
 				resolve(hook, list, idx, add)
 
 			for l in list:
-				debug("Command for hook '%s' in plugin '%s' could not be added due to missing dependant: '%s'!"% (hook, l.hook.plugin.name, l.depend_plugin), warn = 1)
+				warn("Command for hook '%s' in plugin '%s' could not be added due to missing dependant: '%s'!", hook, l.hook.plugin.name, l.depend_plugin)
 
 		for hook in before:
 			resolve(hook, before[hook], 0, 0)
diff --git a/portato/plugins/etc_proposals.py b/portato/plugins/etc_proposals.py
index fa54600..e6c3187 100644
--- a/portato/plugins/etc_proposals.py
+++ b/portato/plugins/etc_proposals.py
@@ -10,7 +10,7 @@
 #
 # Written by René 'Necoro' Neumann <necoro@necoro.net>
 
-from portato.helper import debug, am_i_root
+from portato.helper import *
 from portato.backend import system
 
 from subprocess import Popen
@@ -50,7 +50,7 @@ def etc_prop (*args, **kwargs):
 
 	if float(__version__) < 1.1:
 		l = len(PortatoEtcProposals())
-		debug(l,"files to update")
+		debug("%s files to update.", l)
 
 		if l > 0:
 			Popen(PROG)
@@ -60,7 +60,7 @@ def etc_prop (*args, **kwargs):
 		if f:
 			Popen([PROG, "--fastexit"]+f)
 		else:
-			debug("Cannot start etc-proposals. No graphical frontend installed!", error = 1)
+			error("Cannot start etc-proposals. No graphical frontend installed!")
 
 def etc_prop_menu (*args, **kwargs):
 	if am_i_root():
@@ -72,6 +72,6 @@ def etc_prop_menu (*args, **kwargs):
 			if f:
 				Popen([PROG]+f)
 			else:
-				debug("Cannot start etc-proposals. No graphical frontend installed!", error = 1)
+				error("Cannot start etc-proposals. No graphical frontend installed!")
 	else:
-		debug("Cannot start etc-proposals. Not root!", error = 1)
+		error("Cannot start etc-proposals. Not root!")
diff --git a/portato/plugins/resume_loop.py b/portato/plugins/resume_loop.py
index 9891fee..45c735a 100644
--- a/portato/plugins/resume_loop.py
+++ b/portato/plugins/resume_loop.py
@@ -13,7 +13,7 @@
 import pty
 from subprocess import call, STDOUT
 from portato.backend import system
-from portato.helper import debug
+from portato.helper import debug, warning
 
 console = None
 command = "until emerge --resume --skipfirst; do : ; done"
@@ -24,11 +24,11 @@ def set_console (*args, **kwargs):
 
 def resume_loop (retcode, *args, **kwargs):
 	if retcode is None:
-		debug("Resume-loop called while process is still running!", warn = True)
+		warning("Resume-loop called while process is still running!")
 	elif retcode == 0:
 		# everything ok - ignore
 		#pass
-		debug("Everything is ok")
+		debug("Everything is ok.")
 	else:
 		if console is None:
 			debug("No console for the resume loop...")