Logs errors by default, in a dedicated file

- log_errors option, true by default
- errors go in log_dir/errors.log (so $XDG_DATA_HOME/errors.log
    by default)

This should help a lot for debugging, and provide a way for people
to easily give debug traces without useless or personal infos.

6 files changed, 113 insertions, 24 deletions

diff --git a/src/config.py b/src/config.py
index 34bbfe27..5eed4c09 100644
--- a/src/config.py
+++ b/src/config.py
@@ -22,7 +22,6 @@ from configparser import RawConfigParser, NoOptionError, NoSectionError
 from os import environ, makedirs, path
 from shutil import copy2
 from args import parse_args
-from common import safeJID
 
 
 class Config(RawConfigParser):
@@ -278,3 +277,59 @@ except:
     sys.stderr.write('Poezio was unable to read or parse the config file.\n')
     traceback.print_exc(limit=0)
     sys.exit(1)
+
+LOG_DIR = config.get('log_dir', '') or path.join(environ.get('XDG_DATA_HOME') or path.join(environ.get('HOME'), '.local', 'share'), 'poezio')
+LOG_DIR = path.expanduser(LOG_DIR)
+
+try:
+    makedirs(LOG_DIR)
+except:
+    pass
+
+LOGGING_CONFIG = {
+    'version': 1,
+    'disable_existing_loggers': True,
+    'formatters': {
+        'simple': {
+            'format': '%(levelname)s:%(module)s:%(message)s'
+        }
+    },
+    'handlers': {
+        'debug':{
+            'level':'DEBUG',
+            'class':'logging.FileHandler',
+            'filename': '/tmp/dummy',
+            'formatter': 'simple',
+        },
+        'error': {
+            'level': 'ERROR',
+            'class': 'logging.FileHandler',
+            'filename': '/tmp/dummy',
+            'formatter': 'simple',
+        },
+    },
+    'root': {
+            'handlers': [],
+            'propagate': True,
+            'level': 'DEBUG',
+    }
+}
+if config.get('log_errors', 'true').lower() != 'false':
+    LOGGING_CONFIG['root']['handlers'].append('error')
+    LOGGING_CONFIG['handlers']['error']['filename'] = path.join(
+            LOG_DIR,
+            'errors.log')
+
+if options.debug:
+    LOGGING_CONFIG['root']['handlers'].append('debug')
+    LOGGING_CONFIG['handlers']['debug']['filename'] = options.debug
+
+if LOGGING_CONFIG['root']['handlers']:
+    logging.config.dictConfig(LOGGING_CONFIG)
+else:
+    logging.basicConfig(level=logging.CRITICAL)
+
+# common import sleekxmpp, which creates then its loggers, so
+# it needs to be after logger configuration
+from common import safeJID
+
diff --git a/src/core.py b/src/core.py
index 3bad8c97..22bc0044 100644
--- a/src/core.py
+++ b/src/core.py
@@ -614,12 +614,19 @@ class Core(object):
                 try:
                     self.remote_fifo = Fifo(os.path.join(config.get('remote_fifo_path', './'), 'poezio.fifo'), 'w')
                 except (OSError, IOError) as e:
+                    log.error('Could not open the fifo for writing (%s)',
+                            os.path.join(config.get('remote_fifo_path', './'), 'poezio.fifo'),
+                            exc_info=True)
                     self.information('Could not open fifo file for writing: %s' % (e,), 'Error')
                     return
             command_str = ' '.join([pipes.quote(arg.replace('\n', ' ')) for arg in command]) + '\n'
             try:
                 self.remote_fifo.write(command_str)
             except (IOError) as e:
+                log.error('Could not write in the fifo (%s): %s',
+                            os.path.join(config.get('remote_fifo_path', './'), 'poezio.fifo'),
+                            repr(command),
+                            exc_info=True)
                 self.information('Could not execute %s: %s' % (command, e,), 'Error')
                 self.remote_fifo = None
         else:
@@ -627,6 +634,7 @@ class Core(object):
             try:
                 e.start()
             except ValueError as e:
+                log.error('Could not execute command (%s)', repr(command), exc_info=True)
                 self.information('%s' % (e,), 'Error')
 
 
@@ -644,8 +652,7 @@ class Core(object):
         try:
             self.current_tab().execute_command(line)
         except:
-            import traceback
-            log.debug('Execute failed:\n%s', traceback.format_exc())
+            log.error('Execute failed (%s)', line, exc_info=True)
 
 
 ########################## TImed Events #######################################
@@ -1573,9 +1580,9 @@ class Core(object):
             self.events.trigger('send_normal_presence', pres)
             pres.send()
         except :
-            import traceback
             self.information(_('Could not send directed presence'), 'Error')
-            log.debug(_("Could not send directed presence:\n") + traceback.format_exc())
+            log.debug('Could not send directed presence to %s', jid, exc_info=True)
+            return
         tab = self.get_tab_by_name(jid)
         if tab:
             if type in ('xa', 'away'):
@@ -1623,7 +1630,7 @@ class Core(object):
         try:
             names = os.listdir(themes_dir)
         except OSError as e:
-            log.debug(_('Completion failed: %s'), e)
+            log.error('Completion for /theme failed', exc_info=True)
             return
         theme_files = [name[:-3] for name in names if name.endswith('.py')]
         if not 'default' in theme_files:
@@ -1910,6 +1917,9 @@ class Core(object):
             try:
                 response = self.xmpp.plugin['xep_0030'].get_items(jid=jid.server, block=True, timeout=1)
             except:
+                log.error('/join completion: Unable to get the list of rooms for %s',
+                        jid.server,
+                        exc_info=True)
                 response = None
             if response:
                 items = response['disco_items'].get_items()
@@ -2499,9 +2509,10 @@ class Core(object):
         try:
             StanzaBase(self.xmpp, xml=ET.fromstring(arg)).send()
         except:
-            import traceback
             self.information(_('Could not send custom stanza'), 'Error')
-            log.debug(_("Could not send custom stanza:\n") + traceback.format_exc())
+            log.debug('/rawxml: Could not send custom stanza (%s)',
+                    repr(arg),
+                    exc_info=True)
 
     def command_load(self, arg):
         """
@@ -2886,7 +2897,7 @@ class Core(object):
                             nickname=remote_nick)
                     return True
                 except CorrectionError:
-                    pass
+                    log.error('Unable to correct a message', exc_info=True)
             return False
 
         if not try_modify():
@@ -3106,7 +3117,7 @@ class Core(object):
                     self.events.trigger('highlight', message, tab)
                 replaced = True
             except CorrectionError:
-                pass
+                log.error('Unable to correct a message', exc_info=True)
         if not replaced and tab.add_message(body, date, nick_from, history=delayed, identifier=message['id'], jid=message['from'], typ=1):
             self.events.trigger('highlight', message, tab)
 
@@ -3160,7 +3171,7 @@ class Core(object):
                         nickname=nick_from)
                 replaced = True
             except CorrectionError:
-                pass
+                log.error('Unable to correct a message', exc_info=True)
         if not replaced:
             tab.add_message(body, time=None, nickname=nick_from,
                             forced_user=user,
diff --git a/src/logger.py b/src/logger.py
index dcc49cac..01856e7b 100644
--- a/src/logger.py
+++ b/src/logger.py
@@ -17,8 +17,9 @@ import logging
 
 log = logging.getLogger(__name__)
 
-log_dir = config.get('log_dir', '') or os.path.join(environ.get('XDG_DATA_HOME') or os.path.join(environ.get('HOME'), '.local', 'share'), 'poezio', 'logs')
-log_dir = os.path.expanduser(log_dir)
+from config import LOG_DIR
+
+log_dir = os.path.join(LOG_DIR, 'logs')
 
 message_log_re = re.compile('MR (\d{4})(\d{2})(\d{2})T(\d{2}):(\d{2}):(\d{2})Z (\d+) <([^ ]+)>  (.*)')
 info_log_re = re.compile('MI (\d{4})(\d{2})(\d{2})T(\d{2}):(\d{2}):(\d{2})Z (\d+) (.*)')
@@ -69,13 +70,19 @@ class Logger(object):
             return
         try:
             makedirs(log_dir)
-        except OSError:
+        except FileExistsError:
+            pass
+        except:
+            log.error('Unable to create the log dir', exc_info=True)
             pass
         try:
             fd = open(os.path.join(log_dir, room), 'a')
             self.fds[room] = fd
             return fd
         except IOError:
+            log.error('Unable to open the log file (%s)',
+                    os.path.join(log_dir, room),
+                    exc_info=True)
             return
 
     def get_logs(self, jid, nb=10):
@@ -90,6 +97,9 @@ class Logger(object):
         try:
             fd = open(os.path.join(log_dir, jid), 'rb')
         except:
+            log.error('Unable to open the log file (%s)',
+                    os.path.join(log_dir, room),
+                    exc_info=True)
             return
         if not fd:
             return
@@ -189,11 +199,17 @@ class Logger(object):
             for line in lines:
                 fd.write(' %s\n' % line)
         except:
+            log.error('Unable to write in the log file (%s)',
+                    os.path.join(log_dir, jid),
+                    exc_info=True)
             return False
         else:
             try:
                 fd.flush()          # TODO do something better here?
             except:
+                log.error('Unable to flush the log file (%s)',
+                        os.path.join(log_dir, jid),
+                        exc_info=True)
                 return False
         return True
 
@@ -207,6 +223,9 @@ class Logger(object):
             try:
                 self.roster_logfile = open(os.path.join(log_dir, 'roster.log'), 'a')
             except IOError:
+                log.error('Unable to create the log file (%s)',
+                        os.path.join(log_dir, 'roster.log'),
+                        exc_info=True)
                 return False
         try:
             str_time = datetime.now().strftime('%Y%m%dT%H:%M:%SZ')
@@ -219,6 +238,9 @@ class Logger(object):
                 self.roster_logfile.write(' %s\n' % line)
             self.roster_logfile.flush()
         except:
+            log.error('Unable to write in the log file (%s)',
+                    os.path.join(log_dir, 'roster.log'),
+                    exc_info=True)
             return False
         return True
 
diff --git a/src/poezio.py b/src/poezio.py
index c0863416..43dd6b95 100644
--- a/src/poezio.py
+++ b/src/poezio.py
@@ -14,24 +14,22 @@ import sys
 import os
 
 import signal
-import logging
+import logging.config
 
 sys.path.append(os.path.dirname(os.path.abspath(__file__)))
 
-from logger import logger
 from config import options
+from logger import logger
 import singleton
 import core
 
+log = logging.getLogger('')
+
 def main():
     """
     Enter point
     """
     signal.signal(signal.SIGINT, signal.SIG_IGN) # ignore ctrl-c
-    if options.debug:
-        logging.basicConfig(filename=options.debug, level=logging.DEBUG)
-    else:
-        logging.basicConfig(level=logging.CRITICAL)
     cocore = singleton.Singleton(core.Core)
     signal.signal(signal.SIGUSR1, cocore.sigusr_handler) # reload the config
     signal.signal(signal.SIGHUP, cocore.exit_from_signal)
@@ -48,6 +46,7 @@ def main():
         print("Poezio could not start, maybe you tried aborting it while it was starting?\n"
                 "If you think it is abnormal, please run it with the -d option and report the bug.")
     else:
+        log.error('------------------------ new poezio start ------------------------')
         cocore.main_loop()    # Refresh the screen, wait for user events etc
 
 if __name__ == '__main__':
diff --git a/src/tabs.py b/src/tabs.py
index 6a97e476..80182a52 100644
--- a/src/tabs.py
+++ b/src/tabs.py
@@ -544,6 +544,7 @@ class ChatTab(Tab):
             ET.fromstring(arg)
         except:
             self.core.information('Could not send custom xhtml', 'Error')
+            log.error('/xhtml: Unable to send custom xhtml', exc_info=True)
             return
 
         msg = self.core.xmpp.make_message(self.get_dest_jid())
@@ -1917,7 +1918,7 @@ class PrivateTab(ChatTab):
                             user=user, jid=self.core.xmpp.boundjid, nickname=self.own_nick)
                     replaced = True
                 except:
-                    pass
+                    log.error('Unable to correct a message', exc_info=True)
 
         if not replaced:
             self.add_message(msg['body'],
@@ -2638,6 +2639,7 @@ class RosterInfoTab(Tab):
             handle.close()
         except IOError:
             self.core.information('Could not open %s' % filepath, 'Error')
+            log.error('Unable to correct a message', exc_info=True)
             return
         for jid in lines:
             self.command_add(jid.lstrip('\n'))
@@ -3107,7 +3109,7 @@ class ConversationTab(ChatTab):
                             nickname=self.core.own_nick)
                     replaced = True
                 except:
-                    pass
+                    log.error('Unable to correct a message', exc_info=True)
         if not replaced:
             self.add_message(msg['body'],
                     nickname=self.core.own_nick,
diff --git a/src/xhtml.py b/src/xhtml.py
index f95f3a15..7a3d4da5 100644
--- a/src/xhtml.py
+++ b/src/xhtml.py
@@ -229,8 +229,8 @@ def xhtml_to_poezio_colors(xml):
     if isinstance(xml, str):
         try:
             xml = ET.fromstring(xml)
-        except cElementTree.ParserError as e:
-            log.error("Error decoding XML: [%s] (%s)" % (xml, e))
+        except:
+            log.error("Error decoding XML: [%s]", repr(xml), exc_info=True)
             return ""
     def parse_css(css):
         def get_color(value):