nemunaire/nemubot
1
0
Fork 0
Code Releases Activity

Improve logging system

Browse Source
This commit is contained in:
nemunaire 2014-08-27 07:57:00 +02:00
parent 84d3ee262c
commit e5ec487d29
12 changed files with 75 additions and 80 deletions
Show Stats Download Patch File Download Diff File Expand all files Collapse all files

18
bot.py
View File

@ -32,7 +32,7 @@ from server.IRC import IRCServer
from server.DCC import DCC from server.DCC import DCC
import response import response
logger = logging.getLogger(__name__) logger = logging.getLogger("nemubot.bot")
ID_letters = "abcdefghijklmnopqrstuvwxyzABCDEFGHIJKLMNOPQRSTUVWXYZ" ID_letters = "abcdefghijklmnopqrstuvwxyzABCDEFGHIJKLMNOPQRSTUVWXYZ"
@ -41,7 +41,7 @@ class Bot:
# Bot general informations # Bot general informations
self.version = 3.4 self.version = 3.4
self.version_txt = "3.4-dev" self.version_txt = "3.4-dev"
logger.info("Initiate nemubot v%s" % self.version_txt) logger.info("Initiate nemubot v%s", self.version_txt)
# Save various informations # Save various informations
self.ip = ip self.ip = ip
@ -91,7 +91,7 @@ class Bot:
msg.sender, "USERINFO %s" % self.realname) msg.sender, "USERINFO %s" % self.realname)
self.ctcp_capabilities["VERSION"] = lambda srv, msg: _ctcp_response( self.ctcp_capabilities["VERSION"] = lambda srv, msg: _ctcp_response(
msg.sender, "VERSION nemubot v%s" % self.version_txt) msg.sender, "VERSION nemubot v%s" % self.version_txt)
logger.debug("CTCP capabilities setup: %s" % ", ".join(self.ctcp_capabilities)) logger.debug("CTCP capabilities setup: %s", ", ".join(self.ctcp_capabilities))
def _ctcp_clientinfo(self, srv, msg): def _ctcp_clientinfo(self, srv, msg):
"""Response to CLIENTINFO CTCP message""" """Response to CLIENTINFO CTCP message"""
@ -106,7 +106,7 @@ class Bot:
srv.dcc_clients[conn.sender] = conn srv.dcc_clients[conn.sender] = conn
conn.send_dcc("Hello %s!" % conn.nick) conn.send_dcc("Hello %s!" % conn.nick)
else: else:
logger.error("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): def add_event(self, evt, eid=None, module_src=None):
@ -137,12 +137,12 @@ class Bot:
if module_src is not None: if module_src is not None:
module_src.REGISTERED_EVENTS.append(evt.id) module_src.REGISTERED_EVENTS.append(evt.id)
logger.info("New event registered: %s -> %s" % (evt.id, evt)) logger.info("New event registered: %s -> %s", evt.id, evt)
return evt.id return evt.id
def del_event(self, id, module_src=None): def del_event(self, id, module_src=None):
"""Find and remove an event from list""" """Find and remove an event from list"""
logger.info("Removing event: %s from %s" % (id, module_src)) logger.info("Removing event: %s from %s", id, module_src)
if len(self.events) > 0 and id == self.events[0].id: if len(self.events) > 0 and id == self.events[0].id:
self.events.remove(self.events[0]) self.events.remove(self.events[0])
self.update_timer() self.update_timer()
@ -165,7 +165,7 @@ class Bot:
if self.event_timer is not None: if self.event_timer is not None:
self.event_timer.cancel() self.event_timer.cancel()
if len(self.events) > 0: if len(self.events) > 0:
logger.debug("Update timer: next event in %d seconds" % logger.debug("Update timer: next event in %d seconds",
self.events[0].time_left.seconds) self.events[0].time_left.seconds)
if datetime.now() + timedelta(seconds=5) >= self.events[0].current: if datetime.now() + timedelta(seconds=5) >= self.events[0].current:
while datetime.now() < self.events[0].current: while datetime.now() < self.events[0].current:
@ -247,7 +247,7 @@ class Bot:
self.del_event(e) self.del_event(e)
# Remove from the dict # Remove from the dict
del self.modules[name] del self.modules[name]
logger.info("Module `%s' successfully unloaded." % name) logger.info("Module `%s' successfully unloaded.", name)
return True return True
return False return False
@ -443,7 +443,7 @@ class Bot:
return srv.moremessages[msg.channel] return srv.moremessages[msg.channel]
elif msg.cmds[0] == "dcc": elif msg.cmds[0] == "dcc":
logger.debug("dcctest for " + msg.sender) logger.debug("dcctest for %s", msg.sender)
srv.send_dcc("Hello %s!" % msg.nick, msg.sender) srv.send_dcc("Hello %s!" % msg.nick, msg.sender)
elif msg.cmds[0] == "pvdcctest": elif msg.cmds[0] == "pvdcctest":
logger.debug("dcctest") logger.debug("dcctest")

9
channel.py
View File

@ -16,12 +16,15 @@
# You should have received a copy of the GNU Affero General Public License # You should have received a copy of the GNU Affero General Public License
# along with this program. If not, see <http://www.gnu.org/licenses/>. # along with this program. If not, see <http://www.gnu.org/licenses/>.
import logging
class Channel: class Channel:
def __init__(self, name, password=None): def __init__(self, name, password=None):
self.name = name self.name = name
self.password = password self.password = password
self.people = dict() self.people = dict()
self.topic = "" self.topic = ""
self.logger = logging.getLogger("nemubot.channel." + name)
def treat(self, cmd, msg): def treat(self, cmd, msg):
if cmd == "353": if cmd == "353":
@ -41,7 +44,7 @@ class Channel:
def join(self, nick, level = 0): def join(self, nick, level = 0):
"""Someone join the channel""" """Someone join the channel"""
logger.debug("%s join %s" % (nick, self.name)) self.logger.debug("%s join", nick)
self.people[nick] = level self.people[nick] = level
def chtopic(self, newtopic): def chtopic(self, newtopic):
@ -52,7 +55,7 @@ class Channel:
def nick(self, oldnick, newnick): def nick(self, oldnick, newnick):
"""Someone change his nick""" """Someone change his nick"""
if oldnick in self.people: if oldnick in self.people:
logger.debug("%s switch nick to %s on %s" % (oldnick, newnick, self.name)) self.logger.debug("%s switch nick to %s on", oldnick, newnick)
lvl = self.people[oldnick] lvl = self.people[oldnick]
del self.people[oldnick] del self.people[oldnick]
self.people[newnick] = lvl self.people[newnick] = lvl
@ -60,7 +63,7 @@ class Channel:
def part(self, nick): def part(self, nick):
"""Someone leave the channel""" """Someone leave the channel"""
if nick in self.people: if nick in self.people:
logger.debug("%s has left %s" % (nick, self.name)) self.logger.debug("%s has left", nick)
del self.people[nick] del self.people[nick]
def mode(self, msg): def mode(self, msg):

19
consumer.py
View File

@ -29,7 +29,7 @@ from message import Message
import response import response
import server import server
logger = logging.getLogger(__name__) logger = logging.getLogger("nemubot.consumer")
class MessageConsumer: class MessageConsumer:
"""Store a message before treating""" """Store a message before treating"""
@ -67,7 +67,7 @@ class MessageConsumer:
if (res.server is not None and if (res.server is not None and
not isinstance(res.server, server.Server)): not isinstance(res.server, server.Server)):
logger.error("The server defined in this response doesn't " logger.error("The server defined in this response doesn't "
"exist: %s" % res.server) "exist: %s", res.server)
res.server = None res.server = None
if res.server is None: if res.server is None:
res.server = self.srv res.server = self.srv
@ -80,7 +80,7 @@ class MessageConsumer:
context.hooks.add_hook(res.type, res.hook, res.src) context.hooks.add_hook(res.type, res.hook, res.src)
elif res is not None: elif res is not None:
logger.error("Unrecognized response type: %s" % res) logger.error("Unrecognized response type: %s", res)
def run(self, context): def run(self, context):
"""Create, parse and treat the message""" """Create, parse and treat the message"""
@ -92,12 +92,7 @@ class MessageConsumer:
msg.private = msg.private or msg.channel == self.srv.nick msg.private = msg.private or msg.channel == self.srv.nick
res = self.treat_in(context, msg) res = self.treat_in(context, msg)
except: except:
logger.error("Error occurred during the processing of the message:" logger.exception("Error occurred during the processing of the message: %s", self.raw)
" %s" % self.raw)
exc_type, exc_value, exc_traceback = sys.exc_info()
logger.debug(traceback.format_exception(exc_type,
exc_value,
exc_traceback))
return return
# Send message # Send message
@ -119,11 +114,7 @@ class EventConsumer:
try: try:
self.evt.launch_check() self.evt.launch_check()
except: except:
logger.error("Error during event end") logger.exception("Error during event end")
exc_type, exc_value, exc_traceback = sys.exc_info()
logger.debug(traceback.format_exception(exc_type,
exc_value,
exc_traceback))
if self.evt.next is not None: if self.evt.next is not None:
context.add_event(self.evt, self.evt.id) context.add_event(self.evt, self.evt.id)

10
hooks.py
View File

@ -22,7 +22,7 @@ import re
from response import Response from response import Response
from exception import IRCException from exception import IRCException
logger = logging.getLogger(__name__) logger = logging.getLogger("nemubot.hooks")
class MessagesHook: class MessagesHook:
def __init__(self, context, bot): def __init__(self, context, bot):
@ -54,19 +54,19 @@ class MessagesHook:
def add_hook(self, store, hook, module_src=None): def add_hook(self, store, hook, module_src=None):
"""Insert in the right place a hook into the given store""" """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)) logger.info("Adding hook '%s' to store '%s' from module '%s'", hook, store, module_src)
if module_src is None: if module_src is None:
logger.warn("No source module was passed to add_hook function, " logger.warn("No source module was passed to add_hook function, "
"please fix it in order to be compatible with unload " "please fix it in order to be compatible with unload "
"feature") "feature")
if store in self.context.hooks_cache: if store in self.context.hooks_cache:
logger.debug("Cleaning hooks cache for " + store) logger.debug("Cleaning hooks cache for %s", store)
del self.context.hooks_cache[store] del self.context.hooks_cache[store]
if not hasattr(self, store): if not hasattr(self, store):
# TODO: raise custom exception, this is a user problem, not internal one! # TODO: raise custom exception, this is a user problem, not internal one!
logger.error("Unrecognized hook store: " + store) logger.error("Unrecognized hook store: %s", store)
return return
attr = getattr(self, store) attr = getattr(self, store)
@ -81,7 +81,7 @@ class MessagesHook:
elif isinstance(attr, list): elif isinstance(attr, list):
attr.append(hook) attr.append(hook)
else: else:
logger.critical("Unrecognized hook store type: " + type(attr)) logger.critical("Unrecognized hook store type: %s", type(attr))
return return
if module_src is not None and hasattr(module_src, "REGISTERED_HOOKS"): if module_src is not None and hasattr(module_src, "REGISTERED_HOOKS"):
module_src.REGISTERED_HOOKS.append((store, hook)) module_src.REGISTERED_HOOKS.append((store, hook))

16
importer.py
View File

@ -29,7 +29,7 @@ import hooks
import response import response
import xmlparser import xmlparser
logger = logging.getLogger(__name__) logger = logging.getLogger("nemubot.importer")
class ModuleFinder(Finder): class ModuleFinder(Finder):
def __init__(self, context, prompt): def __init__(self, context, prompt):
@ -146,7 +146,7 @@ class ModuleLoader(SourceLoader):
# Set module common functions and datas # Set module common functions and datas
module.__LOADED__ = True module.__LOADED__ = True
module.logger = logging.getLogger("module/" + fullname) module.logger = logging.getLogger("nemubot.module." + fullname)
def prnt(*args): def prnt(*args):
print("[%s]" % module.name, *args) print("[%s]" % module.name, *args)
@ -165,7 +165,7 @@ class ModuleLoader(SourceLoader):
if server in self.context.servers: if server in self.context.servers:
return self.context.servers[server].send_response(res, None) return self.context.servers[server].send_response(res, None)
else: else:
module.logger.error("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 return False
def add_hook(store, hook): def add_hook(store, hook):
@ -218,8 +218,8 @@ class ModuleLoader(SourceLoader):
break break
if depend["name"] not in module.MODS: if depend["name"] not in module.MODS:
logger.error("In module `%s', module `%s' require by this " logger.error("In module `%s', module `%s' require by this "
"module but is not loaded." % (module.name, "module but is not loaded.", module.name,
depend["name"])) depend["name"])
return return
# Add the module to the global modules list # Add the module to the global modules list
@ -232,9 +232,9 @@ class ModuleLoader(SourceLoader):
# Register hooks # Register hooks
register_hooks(module, self.context, self.prompt) register_hooks(module, self.context, self.prompt)
logger.info("Module '%s' successfully loaded." % module.name) logger.info("Module '%s' successfully loaded.", module.name)
else: else:
logger.error("An error occurs while importing `%s'." % module.name) logger.error("An error occurs while importing `%s'.", module.name)
raise ImportError("An error occurs while importing `%s'." raise ImportError("An error occurs while importing `%s'."
% module.name) % module.name)
return module return module
@ -245,7 +245,7 @@ def add_cap_hook(prompt, module, cmd):
prompt.add_cap_hook(cmd["name"], getattr(module, cmd["call"])) prompt.add_cap_hook(cmd["name"], getattr(module, cmd["call"]))
else: else:
logger.warn("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"])) "command hook.", module.name, cmd["call"], cmd["name"])
def register_hooks(module, context, prompt): def register_hooks(module, context, prompt):
"""Register all available hooks""" """Register all available hooks"""

27
nemubot.py
View File

@ -30,9 +30,19 @@ import importer
if __name__ == "__main__": if __name__ == "__main__":
# Setup loggin interface # Setup loggin interface
logging.basicConfig(filename='nemubot.log', level=logging.DEBUG) logger = logging.getLogger("nemubot")
logging.Formatter('%(asctime)s %(name)s %(levelname)s %(message)s')
logger = logging.getLogger(__name__) formatter = logging.Formatter('%(asctime)s %(name)s %(levelname)s %(message)s')
ch = logging.StreamHandler()
ch.setFormatter(formatter)
ch.setLevel(logging.INFO)
logger.addHandler(ch)
fh = logging.FileHandler('./nemubot.log')
fh.setFormatter(formatter)
fh.setLevel(logging.DEBUG)
logger.addHandler(fh)
# Create bot context # Create bot context
context = bot.Bot(0, "FIXME") context = bot.Bot(0, "FIXME")
@ -68,14 +78,11 @@ if __name__ == "__main__":
prmpt = prompt.hotswap(prmpt) prmpt = prompt.hotswap(prmpt)
# Reload all other modules # Reload all other modules
bot.reload() bot.reload()
print ("\033[1;32mContext reloaded\033[0m, now in Nemubot %s" % print("\033[1;32mContext reloaded\033[0m, now in Nemubot %s" %
context.version_txt) context.version_txt)
except: except:
print ("\033[1;31mUnable to reload the prompt due to errors.\033[0" logger.exception("\033[1;31mUnable to reload the prompt due to errors.\033[0"
"m Fix them before trying to reload the prompt.") "m Fix them before trying to reload the prompt.")
exc_type, exc_value, exc_traceback = sys.exc_info()
sys.stderr.write (traceback.format_exception_only(exc_type,
exc_value)[0])
print ("\nWaiting for other threads shuts down...") print ("\nWaiting for other threads shuts down...")

10
prompt/builtins.py
View File

@ -20,7 +20,7 @@ import logging
import os import os
import xmlparser import xmlparser
logger = logging.getLogger(__name__) logger = logging.getLogger("nemubot.prompt.builtins")
def end(toks, context, prompt): def end(toks, context, prompt):
"""Quit the prompt for reload or exit""" """Quit the prompt for reload or exit"""
@ -69,11 +69,11 @@ def load_file(filename, context):
if context.addServer(server, config["nick"], if context.addServer(server, config["nick"],
config["owner"], config["realname"], config["owner"], config["realname"],
server.hasAttribute("ssl")): server.hasAttribute("ssl")):
logger.info("Server `%s:%s' successfully added." logger.info("Server `%s:%s' successfully added.",
% (server["server"], server["port"])) server["server"], server["port"])
else: else:
logger.warn("Server `%s:%s' already added, skiped." logger.warn("Server `%s:%s' already added, skiped.",
% (server["server"], server["port"])) server["server"], server["port"])
# Load files asked by the configuration file # Load files asked by the configuration file
for load in config.getNodes("load"): for load in config.getNodes("load"):

7
response.py
View File

@ -20,7 +20,7 @@ import logging
import traceback import traceback
import sys import sys
logger = logging.getLogger(__name__) logger = logging.getLogger("nemubot.response")
class Response: class Response:
def __init__(self, sender, message=None, channel=None, nick=None, server=None, def __init__(self, sender, message=None, channel=None, nick=None, server=None,
@ -56,10 +56,7 @@ class Response:
def set_sender(self, sender): def set_sender(self, sender):
if sender is None or sender.find("!") < 0: if sender is None or sender.find("!") < 0:
if sender is not None: if sender is not None:
exc_type, exc_value, exc_traceback = sys.exc_info() logger.warn("Bad sender provided in Response, it will be ignored.", stack_info=True)
logger.warn(traceback.format_exception(exc_type,
"Bad sender provided in Response, it will be ignored.",
exc_traceback))
self.sender = None self.sender = None
else: else:
self.sender = sender self.sender = sender

10
server/DCC.py
View File

@ -81,7 +81,7 @@ class DCC(server.Server):
self.s = socket.socket() self.s = socket.socket()
try: try:
self.s.connect((host, port)) self.s.connect((host, port))
self.logger.info("Accepted user from %s:%d for %s" % (host, port, self.sender)) self.logger.info("Accepted user from %s:%d for %s", host, port, self.sender)
self.connected = True self.connected = True
self.stop = False self.stop = False
except: except:
@ -106,7 +106,7 @@ class DCC(server.Server):
self.setError("Une erreur s'est produite durant la tentative" self.setError("Une erreur s'est produite durant la tentative"
" d'ouverture d'une session DCC.") " d'ouverture d'une session DCC.")
return False return False
self.logger.info("Listening on %d for %s" % (self.port, self.sender)) self.logger.info("Listening on %d for %s", self.port, self.sender)
#Send CTCP request for DCC #Send CTCP request for DCC
self.srv.send_ctcp(self.sender, self.srv.send_ctcp(self.sender,
@ -117,7 +117,7 @@ class DCC(server.Server):
s.listen(1) s.listen(1)
#Waiting for the client #Waiting for the client
(self.s, addr) = s.accept() (self.s, addr) = s.accept()
self.logger.info("Connected by %d" % addr) self.logger.info("Connected by %d", addr)
self.connected = True self.connected = True
return True return True
@ -151,7 +151,7 @@ class DCC(server.Server):
except RuntimeError: except RuntimeError:
pass pass
else: else:
self.logger.error("File not found `%s'" % filename) self.logger.error("File not found `%s'", filename)
def run(self): def run(self):
self.stopping.clear() self.stopping.clear()
@ -204,7 +204,7 @@ class DCC(server.Server):
if self.realname in self.srv.dcc_clients: if self.realname in self.srv.dcc_clients:
del self.srv.dcc_clients[self.realname] del self.srv.dcc_clients[self.realname]
self.logger.info("Closing connection with " + self.nick) self.logger.info("Closing connection with %s", self.nick)
self.stopping.set() self.stopping.set()
if self.closing_event is not None: if self.closing_event is not None:
self.closing_event() self.closing_event()

19
server/IRC.py
View File

@ -173,8 +173,8 @@ class IRCServer(server.Server):
self.s.connect((self.host, self.port)) #Connect to server self.s.connect((self.host, self.port)) #Connect to server
except socket.error as e: except socket.error as e:
self.s = None self.s = None
self.logger.critical("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))) self.host, self.port, os.strerror(e.errno))
return return
self.stopping.clear() self.stopping.clear()
@ -185,10 +185,10 @@ class IRCServer(server.Server):
self.realname)).encode()) self.realname)).encode())
raw = self.s.recv(1024) raw = self.s.recv(1024)
if not raw: if not raw:
self.logger.critical("Unable to connect to %s:%d" % (self.host, self.port)) self.logger.critical("Unable to connect to %s:%d", self.host, self.port)
return return
self.connected = True self.connected = True
self.logger.info("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: if len(self.channels) > 0:
for chn in self.channels.keys(): for chn in self.channels.keys():
@ -214,7 +214,7 @@ class IRCServer(server.Server):
self.connected = False self.connected = False
if self.closing_event is not None: if self.closing_event is not None:
self.closing_event() self.closing_event()
self.logger.info("Server `%s' successfully stopped." % self.id) self.logger.info("Server `%s' successfully stopped.", self.id)
self.stopping.set() self.stopping.set()
# Rearm Thread # Rearm Thread
threading.Thread.__init__(self) threading.Thread.__init__(self)
@ -255,17 +255,14 @@ class IRCServer(server.Server):
"""Send a message without checks or format""" """Send a message without checks or format"""
#TODO: add something for post message treatment here #TODO: add something for post message treatment here
if channel == self.nick: if channel == self.nick:
self.logger.warn("Nemubot talks to himself: %s" % msg) self.logger.warn("Nemubot talks to himself: %s", msg, stack_info=True)
self.logger.debug(traceback.print_stack())
if line is not None and channel is not None: if line is not None and channel is not None:
if self.s is None: if self.s is None:
self.logger.warn("Attempt to send message on a non connected server: %s: %s" % (self.id, line)) self.logger.warn("Attempt to send message on a non connected server: %s: %s", self.id, line, stack_info=True)
self.logger.debug(traceback.format_stack())
elif len(line) < 442: 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: else:
self.logger.warn("Message truncated due to size (%d ; max : 442) : %s" % (len(line), line)) self.logger.warn("Message truncated due to size (%d ; max : 442) : %s", len(line), line, stack_info=True)
self.logger.debug(traceback.format_stack())
self.s.send (("%s %s :%s%s" % (cmd, channel, line[0:442]+"<…>", endl)).encode ()) self.s.send (("%s %s :%s%s" % (cmd, channel, line[0:442]+"<…>", endl)).encode ())
def send_msg_usr(self, user, msg): def send_msg_usr(self, user, msg):

2
server/__init__.py
View File

@ -30,7 +30,7 @@ class Server(threading.Thread):
self.moremessages = dict() self.moremessages = dict()
self.logger = logging.getLogger(__name__ + "/" + self.id) self.logger = logging.getLogger("nemubot.server." + self.id)
threading.Thread.__init__(self) threading.Thread.__init__(self)

8
xmlparser/node.py
View File

@ -3,10 +3,13 @@
import xml.sax import xml.sax
from datetime import datetime from datetime import datetime
from datetime import date from datetime import date
import logging
import sys import sys
import time import time
import traceback import traceback
logger = logging.getLogger("nemubot.xmlparser.node")
class ModuleState: class ModuleState:
"""Tiny tree representation of an XML file""" """Tiny tree representation of an XML file"""
@ -192,10 +195,7 @@ class ModuleState:
gen.endElement(self.name) gen.endElement(self.name)
except: except:
print ("\033[1;31mERROR:\033[0m occurred when saving the " logger.exception("Error occured when saving the following XML node: %s with %s", self.name, attrs)
"following XML node: %s with %s" % (self.name, attrs))
exc_type, exc_value, exc_traceback = sys.exc_info()
traceback.print_exception(exc_type, exc_value, exc_traceback)
def save(self, filename): def save(self, filename):
"""Save the current node as root node in a XML file""" """Save the current node as root node in a XML file"""