From d0b1336d073d3cadb9c96265ccc244db32db8f73 Mon Sep 17 00:00:00 2001 From: nemunaire Date: Thu, 14 Aug 2014 12:49:38 +0200 Subject: [PATCH] Use a logger --- .gitignore | 1 + bot.py | 39 +++++++++++++++++++++++---------------- channel.py | 6 +++--- consumer.py | 26 +++++++++++++++----------- hooks.py | 18 ++++++++++++------ importer.py | 24 ++++++++++++++++-------- message.py | 3 --- nemubot.py | 10 ++++++++-- prompt/__init__.py | 6 +++--- prompt/builtins.py | 11 +++++++---- response.py | 7 ++++++- server/DCC.py | 12 ++++++------ server/IRC.py | 26 +++++++++++++------------- server/__init__.py | 6 +++++- 14 files changed, 118 insertions(+), 77 deletions(-) diff --git a/.gitignore b/.gitignore index 50aca48..6e6afac 100644 --- a/.gitignore +++ b/.gitignore @@ -1,5 +1,6 @@ *# *~ +*.log TAGS *.py[cod] __pycache__ diff --git a/bot.py b/bot.py index e87cd1a..3e60b8c 100644 --- a/bot.py +++ b/bot.py @@ -18,6 +18,7 @@ from datetime import datetime from datetime import timedelta +import logging from queue import Queue import threading import time @@ -31,6 +32,8 @@ from server.IRC import IRCServer from server.DCC import DCC import response +logger = logging.getLogger(__name__) + ID_letters = "abcdefghijklmnopqrstuvwxyzABCDEFGHIJKLMNOPQRSTUVWXYZ" class Bot: @@ -38,6 +41,7 @@ class Bot: # Bot general informations self.version = 3.4 self.version_txt = "3.4-dev" + logger.info("Initiate nemubot v%s" % self.version_txt) # Save various informations self.ip = ip @@ -87,6 +91,7 @@ class Bot: msg.sender, "USERINFO %s" % self.realname) self.ctcp_capabilities["VERSION"] = lambda srv, msg: _ctcp_response( msg.sender, "VERSION nemubot v%s" % self.version_txt) + logger.debug("CTCP capabilities setup: %s" % ", ".join(self.ctcp_capabilities)) def _ctcp_clientinfo(self, srv, msg): """Response to CLIENTINFO CTCP message""" @@ -101,7 +106,7 @@ class Bot: srv.dcc_clients[conn.sender] = conn conn.send_dcc("Hello %s!" % conn.nick) else: - print ("DCC: unable to connect to %s:%s" % (ip, msg.cmds[4])) + logger.error("DCC: unable to connect to %s:%s" % (ip, msg.cmds[4])) def add_event(self, evt, eid=None, module_src=None): @@ -132,10 +137,12 @@ class Bot: if module_src is not None: module_src.REGISTERED_EVENTS.append(evt.id) + logger.info("New event registered: %s -> %s" % (evt.id, evt)) return evt.id def del_event(self, id, module_src=None): """Find and remove an event from list""" + logger.info("Removing event: %s from %s" % (id, module_src)) if len(self.events) > 0 and id == self.events[0].id: self.events.remove(self.events[0]) self.update_timer() @@ -158,8 +165,8 @@ class Bot: if self.event_timer is not None: self.event_timer.cancel() if len(self.events) > 0: - #print ("Update timer, next in", self.events[0].time_left.seconds, - # "seconds") + logger.debug("Update timer: next event in %d seconds" % + self.events[0].time_left.seconds) if datetime.now() + timedelta(seconds=5) >= self.events[0].current: while datetime.now() < self.events[0].current: time.sleep(0.6) @@ -168,13 +175,13 @@ class Bot: self.event_timer = threading.Timer( self.events[0].time_left.seconds + 1, self.end_timer) self.event_timer.start() - #else: - # print ("Update timer: no timer left") + else: + logger.debug("Update timer: no timer left") def end_timer(self): """Function called at the end of the timer""" #print ("end timer") - while len(self.events)>0 and datetime.now() >= self.events[0].current: + while len(self.events) > 0 and datetime.now() >= self.events[0].current: #print ("end timer: while") evt = self.events.pop(0) self.cnsr_queue.put_nowait(consumer.EventConsumer(evt)) @@ -225,7 +232,7 @@ class Bot: return False - def unload_module(self, name, verb=False): + def unload_module(self, name): """Unload a module""" if name in self.modules: self.modules[name].print_debug("Unloading module %s" % name) @@ -240,7 +247,7 @@ class Bot: self.del_event(e) # Remove from the dict del self.modules[name] - print(" Module `%s' successfully unloaded." % name) + logger.info("Module `%s' successfully unloaded." % name) return True return False @@ -274,18 +281,18 @@ class Bot: if self.network[bot].srv == srv: self.network[bot].send_cmd(cmd, data) - def quit(self, verb=False): + def quit(self): """Save and unload modules and disconnect servers""" if self.event_timer is not None: - if verb: print ("Stop the event timer...") + logger.info("Stop the event timer...") self.event_timer.cancel() - if verb: print ("Save and unload all modules...") + logger.info("Save and unload all modules...") k = list(self.modules.keys()) for mod in k: - self.unload_module(mod, verb) + self.unload_module(mod) - if verb: print ("Close all servers connection...") + logger.info("Close all servers connection...") k = list(self.servers.keys()) for srv in k: self.servers[srv].disconnect() @@ -436,13 +443,13 @@ class Bot: return srv.moremessages[msg.channel] elif msg.cmds[0] == "dcc": - print("dcctest for", msg.sender) + logger.debug("dcctest for " + msg.sender) srv.send_dcc("Hello %s!" % msg.nick, msg.sender) elif msg.cmds[0] == "pvdcctest": - print("dcctest") + logger.debug("dcctest") return Response(msg.sender, message="Test DCC") elif msg.cmds[0] == "dccsendtest": - print("dccsendtest") + logger.debug("dccsendtest") conn = DCC(srv, msg.sender) conn.send_file("bot_sample.xml") diff --git a/channel.py b/channel.py index 6a67d76..974713f 100644 --- a/channel.py +++ b/channel.py @@ -41,7 +41,7 @@ class Channel: def join(self, nick, level = 0): """Someone join the channel""" - #print ("%s arrive sur %s" % (nick, self.name)) + logger.debug("%s join %s" % (nick, self.name)) self.people[nick] = level def chtopic(self, newtopic): @@ -52,7 +52,7 @@ class Channel: def nick(self, oldnick, newnick): """Someone change his nick""" if oldnick in self.people: - #print ("%s change de nom pour %s sur %s" % (oldnick, newnick, self.name)) + logger.debug("%s switch nick to %s on %s" % (oldnick, newnick, self.name)) lvl = self.people[oldnick] del self.people[oldnick] self.people[newnick] = lvl @@ -60,7 +60,7 @@ class Channel: def part(self, nick): """Someone leave the channel""" if nick in self.people: - #print ("%s vient de quitter %s" % (nick, self.name)) + logger.debug("%s has left %s" % (nick, self.name)) del self.people[nick] def mode(self, msg): diff --git a/consumer.py b/consumer.py index 009eebf..ea63e1c 100644 --- a/consumer.py +++ b/consumer.py @@ -16,6 +16,7 @@ # You should have received a copy of the GNU Affero General Public License # along with this program. If not, see . +import logging import queue import re import threading @@ -28,6 +29,8 @@ from message import Message import response import server +logger = logging.getLogger(__name__) + class MessageConsumer: """Store a message before treating""" def __init__(self, srv, raw, time, prvt, data): @@ -63,8 +66,8 @@ class MessageConsumer: res.server = context.servers[res.server] if (res.server is not None and not isinstance(res.server, server.Server)): - print ("\033[1;35mWarning:\033[0m the server defined in this " - "response doesn't exist: %s" % (res.server)) + logger.error("The server defined in this response doesn't " + "exist: %s" % res.server) res.server = None if res.server is None: res.server = self.srv @@ -77,8 +80,7 @@ class MessageConsumer: context.hooks.add_hook(res.type, res.hook, res.src) elif res is not None: - print ("\033[1;35mWarning:\033[0m unrecognized response type " - ": %s" % res) + logger.error("Unrecognized response type: %s" % res) def run(self, context): """Create, parse and treat the message""" @@ -90,11 +92,12 @@ class MessageConsumer: msg.private = msg.private or msg.channel == self.srv.nick res = self.treat_in(context, msg) except: - print ("\033[1;31mERROR:\033[0m occurred during the " - "processing of the message: %s" % self.raw) + logger.error("Error occurred during the processing of the message:" + " %s" % self.raw) exc_type, exc_value, exc_traceback = sys.exc_info() - traceback.print_exception(exc_type, exc_value, - exc_traceback) + logger.debug(traceback.format_exception(exc_type, + exc_value, + exc_traceback)) return # Send message @@ -116,10 +119,11 @@ class EventConsumer: try: self.evt.launch_check() except: - print ("\033[1;31mError:\033[0m during event end") + logger.error("Error during event end") exc_type, exc_value, exc_traceback = sys.exc_info() - traceback.print_exception(exc_type, exc_value, - exc_traceback) + logger.debug(traceback.format_exception(exc_type, + exc_value, + exc_traceback)) if self.evt.next is not None: context.add_event(self.evt, self.evt.id) diff --git a/hooks.py b/hooks.py index f9002e0..48c47ac 100644 --- a/hooks.py +++ b/hooks.py @@ -16,11 +16,14 @@ # You should have received a copy of the GNU Affero General Public License # along with this program. If not, see . +import logging import re from response import Response from exception import IRCException +logger = logging.getLogger(__name__) + class MessagesHook: def __init__(self, context, bot): self.context = context @@ -51,16 +54,19 @@ class MessagesHook: def add_hook(self, store, hook, module_src=None): """Insert in the right place a hook into the given store""" + logger.info("Adding hook '%s' to store '%s' from module '%s'" % (hook, store, module_src)) if module_src is None: - print ("\033[1;35mWarning:\033[0m No source module was passed to " - "add_hook function, please fix it in order to be " - "compatible with unload feature") + logger.warn("No source module was passed to add_hook function, " + "please fix it in order to be compatible with unload " + "feature") if store in self.context.hooks_cache: + logger.debug("Cleaning hooks cache for " + store) del self.context.hooks_cache[store] if not hasattr(self, store): - print ("\033[1;35mWarning:\033[0m unrecognized hook store") + # TODO: raise custom exception, this is a user problem, not internal one! + logger.error("Unrecognized hook store: " + store) return attr = getattr(self, store) @@ -75,7 +81,7 @@ class MessagesHook: elif isinstance(attr, list): attr.append(hook) else: - print ("\033[1;32mWarning:\033[0m unrecognized hook store type") + logger.critical("Unrecognized hook store type: " + type(attr)) return if module_src is not None and hasattr(module_src, "REGISTERED_HOOKS"): module_src.REGISTERED_HOOKS.append((store, hook)) @@ -147,7 +153,7 @@ class MessagesHook: del self.context.hooks_cache[store] if not hasattr(self, store): - print ("Warning: unrecognized hook store type") + logger.warn("unrecognized hook store type") return attr = getattr(self, store) diff --git a/importer.py b/importer.py index d7d0c80..4b435dc 100644 --- a/importer.py +++ b/importer.py @@ -19,6 +19,7 @@ from importlib.abc import Finder from importlib.abc import SourceLoader import imp +import logging import os import sys @@ -28,6 +29,8 @@ import hooks import response import xmlparser +logger = logging.getLogger(__name__) + class ModuleFinder(Finder): def __init__(self, context, prompt): self.context = context @@ -143,22 +146,26 @@ class ModuleLoader(SourceLoader): # Set module common functions and datas module.__LOADED__ = True + module.logger = logging.getLogger("module/" + fullname) def prnt(*args): print("[%s]" % module.name, *args) + module.logger.info(*args) def prnt_dbg(*args): if module.DEBUG: print("{%s}" % module.name, *args) + module.logger.debug(*args) def mod_save(): - module.print_debug("Saving DATAS...") - module.DATAS.save(self.context.datas_path + "/" + module.name + ".xml") + fpath = self.context.datas_path + "/" + module.name + ".xml" + module.print_debug("Saving DATAS to " + fpath) + module.DATAS.save(fpath) def send_response(server, res): if server in self.context.servers: return self.context.servers[server].send_response(res, None) else: - print("\033[1;35mWarning:\033[0m Try to send a message to the unknown server: %s" % server) + module.logger.error("Try to send a message to the unknown server: %s" % server) return False def add_hook(store, hook): @@ -210,9 +217,9 @@ class ModuleLoader(SourceLoader): mod.MODS[md.name] = md break if depend["name"] not in module.MODS: - print ("\033[1;31mERROR:\033[0m in module `%s', module " - "`%s' require by this module but is not loaded." - % (module.name, depend["name"])) + logger.error("In module `%s', module `%s' require by this " + "module but is not loaded." % (module.name, + depend["name"])) return # Add the module to the global modules list @@ -225,8 +232,9 @@ class ModuleLoader(SourceLoader): # Register hooks register_hooks(module, self.context, self.prompt) - print (" Module `%s' successfully loaded." % module.name) + logger.info("Module '%s' successfully loaded." % module.name) else: + logger.error("An error occurs while importing `%s'." % module.name) raise ImportError("An error occurs while importing `%s'." % module.name) return module @@ -236,7 +244,7 @@ def add_cap_hook(prompt, module, cmd): if hasattr(module, cmd["call"]): prompt.add_cap_hook(cmd["name"], getattr(module, cmd["call"])) else: - print ("Warning: In module `%s', no function `%s' defined for `%s' " + logger.warn("In module `%s', no function `%s' defined for `%s' " "command hook." % (module.name, cmd["call"], cmd["name"])) def register_hooks(module, context, prompt): diff --git a/message.py b/message.py index c6a5d8c..aa2b6e0 100644 --- a/message.py +++ b/message.py @@ -76,10 +76,8 @@ class Message: self.channel = words[3] self.content = self.pickWords(words[4:]) else: - #print (line) self.content = self.pickWords(words[3:]) else: - print (line) if self.cmd == 'PRIVMSG': self.channel = words[2].decode() self.content = b' '.join(words[3:]) @@ -247,7 +245,6 @@ class Message: minute = result.group(9) second = result.group(11) - print ("Chaîne reconnue : %s/%s/%s %s:%s:%s"%(day, month, year, hour, minute, second)) if year == None: year = date.today().year if hour == None: diff --git a/nemubot.py b/nemubot.py index 4e77007..66fc396 100755 --- a/nemubot.py +++ b/nemubot.py @@ -17,9 +17,10 @@ # You should have received a copy of the GNU Affero General Public License # along with this program. If not, see . -import sys -import os import imp +import logging +import os +import sys import traceback import bot @@ -28,6 +29,11 @@ from prompt.builtins import load_file import importer if __name__ == "__main__": + # Setup loggin interface + logging.basicConfig(filename='nemubot.log', level=logging.DEBUG) + logging.Formatter('%(asctime)s %(name)s %(levelname)s %(message)s') + logger = logging.getLogger(__name__) + # Create bot context context = bot.Bot(0, "FIXME") diff --git a/prompt/__init__.py b/prompt/__init__.py index 62c8dc3..6504744 100644 --- a/prompt/__init__.py +++ b/prompt/__init__.py @@ -67,7 +67,7 @@ class Prompt: (f,d) = self.HOOKS_CAPS[toks[0]] return f(d, toks, context, self) else: - print ("Unknown command: `%s'" % toks[0]) + print("Unknown command: `%s'" % toks[0]) return "" def getPS1(self): @@ -88,7 +88,7 @@ class Prompt: line = sys.stdin.readline() if len(line) <= 0: line = "quit" - print ("quit") + print("quit") cmds = self.lex_cmd(line.strip()) for toks in cmds: try: @@ -97,7 +97,7 @@ class Prompt: exc_type, exc_value, exc_traceback = sys.exc_info() traceback.print_exception(exc_type, exc_value, exc_traceback) except KeyboardInterrupt: - print ("") + print("") return ret != "quit" diff --git a/prompt/builtins.py b/prompt/builtins.py index 6e7aa5a..4e0b0d7 100644 --- a/prompt/builtins.py +++ b/prompt/builtins.py @@ -16,9 +16,12 @@ # You should have received a copy of the GNU Affero General Public License # along with this program. If not, see . +import logging import os import xmlparser +logger = logging.getLogger(__name__) + def end(toks, context, prompt): """Quit the prompt for reload or exit""" if toks[0] == "refresh": @@ -66,11 +69,11 @@ def load_file(filename, context): if context.addServer(server, config["nick"], config["owner"], config["realname"], server.hasAttribute("ssl")): - print (" Server `%s:%s' successfully added." - % (server["server"], server["port"])) + logger.info("Server `%s:%s' successfully added." + % (server["server"], server["port"])) else: - print (" Server `%s:%s' already added, skiped." - % (server["server"], server["port"])) + logger.warn("Server `%s:%s' already added, skiped." + % (server["server"], server["port"])) # Load files asked by the configuration file for load in config.getNodes("load"): diff --git a/response.py b/response.py index 9fda7f8..0716180 100644 --- a/response.py +++ b/response.py @@ -16,9 +16,12 @@ # You should have received a copy of the GNU Affero General Public License # along with this program. If not, see . +import logging import traceback import sys +logger = logging.getLogger(__name__) + class Response: def __init__(self, sender, message=None, channel=None, nick=None, server=None, nomore="No more message", title=None, more="(suite) ", count=None, @@ -54,7 +57,9 @@ class Response: if sender is None or sender.find("!") < 0: if sender is not None: exc_type, exc_value, exc_traceback = sys.exc_info() - traceback.print_exception(exc_type, "\033[1;35mWarning:\033[0m bad sender provided in Response, it will be ignored.", exc_traceback) + logger.warn(traceback.format_exception(exc_type, + "Bad sender provided in Response, it will be ignored.", + exc_traceback)) self.sender = None else: self.sender = sender diff --git a/server/DCC.py b/server/DCC.py index 5dc46ea..2a0b741 100644 --- a/server/DCC.py +++ b/server/DCC.py @@ -55,7 +55,7 @@ class DCC(server.Server): self.port = self.foundPort() if self.port is None: - print ("No more available slot for DCC connection") + self.logger.critical("No more available slot for DCC connection") self.setError("Il n'y a plus de place disponible sur le serveur" " pour initialiser une session DCC.") @@ -81,7 +81,7 @@ class DCC(server.Server): self.s = socket.socket() try: self.s.connect((host, port)) - print ('Accepted user from', host, port, "for", self.sender) + self.logger.info("Accepted user from %s:%d for %s" % (host, port, self.sender)) self.connected = True self.stop = False except: @@ -106,7 +106,7 @@ class DCC(server.Server): self.setError("Une erreur s'est produite durant la tentative" " d'ouverture d'une session DCC.") return False - print ('Listen on', self.port, "for", self.sender) + self.logger.info("Listening on %d for %s" % (self.port, self.sender)) #Send CTCP request for DCC self.srv.send_ctcp(self.sender, @@ -117,7 +117,7 @@ class DCC(server.Server): s.listen(1) #Waiting for the client (self.s, addr) = s.accept() - print ('Connected by', addr) + self.logger.info("Connected by %d" % addr) self.connected = True return True @@ -151,7 +151,7 @@ class DCC(server.Server): except RuntimeError: pass else: - print("File not found `%s'" % filename) + self.logger.error("File not found `%s'" % filename) def run(self): self.stopping.clear() @@ -204,7 +204,7 @@ class DCC(server.Server): if self.realname in self.srv.dcc_clients: del self.srv.dcc_clients[self.realname] - print ("Closing connection with", self.nick) + self.logger.info("Closing connection with " + self.nick) self.stopping.set() if self.closing_event is not None: self.closing_event() diff --git a/server/IRC.py b/server/IRC.py index 6cec073..2029340 100644 --- a/server/IRC.py +++ b/server/IRC.py @@ -43,10 +43,10 @@ class IRCServer(server.Server): realname -- string used as realname on this server ssl -- require SSL? """ - server.Server.__init__(self) - self.node = node + server.Server.__init__(self) + self.nick = nick self.owner = owner self.realname = realname @@ -173,7 +173,7 @@ class IRCServer(server.Server): self.s.connect((self.host, self.port)) #Connect to server except socket.error as e: self.s = None - print ("\033[1;31mError:\033[0m Unable to connect to %s:%d: %s" + self.logger.critical("Unable to connect to %s:%d: %s" % (self.host, self.port, os.strerror(e.errno))) return self.stopping.clear() @@ -185,10 +185,10 @@ class IRCServer(server.Server): self.realname)).encode()) raw = self.s.recv(1024) if not raw: - print ("Unable to connect to %s:%d" % (self.host, self.port)) + self.logger.critical("Unable to connect to %s:%d" % (self.host, self.port)) return self.connected = True - print ("Connection to %s:%d completed" % (self.host, self.port)) + self.logger.info("Connection to %s:%d completed" % (self.host, self.port)) if len(self.channels) > 0: for chn in self.channels.keys(): @@ -214,7 +214,7 @@ class IRCServer(server.Server): self.connected = False if self.closing_event is not None: self.closing_event() - print ("Server `%s' successfully stopped." % self.id) + self.logger.info("Server `%s' successfully stopped." % self.id) self.stopping.set() # Rearm Thread threading.Thread.__init__(self) @@ -255,17 +255,17 @@ class IRCServer(server.Server): """Send a message without checks or format""" #TODO: add something for post message treatment here if channel == self.nick: - print ("\033[1;35mWarning:\033[0m Nemubot talks to himself: %s" % msg) - traceback.print_stack() + self.logger.warn("Nemubot talks to himself: %s" % msg) + self.logger.debug(traceback.print_stack()) if line is not None and channel is not None: if self.s is None: - print ("\033[1;35mWarning:\033[0m Attempt to send message on a non connected server: %s: %s" % (self.id, line)) - traceback.print_stack() + self.logger.warn("Attempt to send message on a non connected server: %s: %s" % (self.id, line)) + self.logger.debug(traceback.format_stack()) elif len(line) < 442: - self.s.send (("%s %s :%s%s" % (cmd, channel, line, endl)).encode ()) + self.s.send(("%s %s :%s%s" % (cmd, channel, line, endl)).encode ()) else: - print ("\033[1;35mWarning:\033[0m Message truncated due to size (%d ; max : 442) : %s" % (len(line), line)) - traceback.print_stack() + self.logger.warn("Message truncated due to size (%d ; max : 442) : %s" % (len(line), line)) + self.logger.debug(traceback.format_stack()) self.s.send (("%s %s :%s%s" % (cmd, channel, line[0:442]+"<…>", endl)).encode ()) def send_msg_usr(self, user, msg): diff --git a/server/__init__.py b/server/__init__.py index e16bd57..590a194 100644 --- a/server/__init__.py +++ b/server/__init__.py @@ -16,6 +16,7 @@ # You should have received a copy of the GNU Affero General Public License # along with this program. If not, see . +import logging import socket import threading @@ -29,6 +30,8 @@ class Server(threading.Thread): self.moremessages = dict() + self.logger = logging.getLogger(__name__ + "/" + self.id) + threading.Thread.__init__(self) def isDCC(self, to=None): @@ -142,7 +145,7 @@ class Server(threading.Thread): self.connected = False #Send a message in order to close the socket try: - self.s.send(("Bye!\r\n" % self.nick).encode ()) + self.s.send(("Bye!\r\n").encode ()) except: pass self.stopping.wait() @@ -155,6 +158,7 @@ class Server(threading.Thread): self._receive_action = receive_action if not self.connected: self.stop = False + self.logger.info("Entering main loop for server") try: self.start() except RuntimeError: