Merge pull request #86 from SunilMohanAdapa/python-logging

Python logging

logger.py

@@ -1,40 +0,0 @@
-import cherrypy
-import inspect
-import cfg
-
-
-def init():
-    """Initialize logging"""
-    cherrypy.log.error_file = cfg.status_log_file
-    cherrypy.log.access_file = cfg.access_log_file
-    if not cfg.no_daemon:
-        cherrypy.log.screen = False
-
-
-class Logger(object):
-    """By convention, log levels are DEBUG, INFO, WARNING, ERROR and CRITICAL."""
-    def log(self, msg, level="DEBUG"):
-        cherrypy.log.error("%s %s" % (level, msg), inspect.stack()[2][3], 20)
-    def __call__(self, *args):
-        self.log(*args)
-
-    def debug(self, msg):
-        self.log(msg)
-
-    def info(self, msg):
-        self.log(msg, "INFO")
-
-    def warn(self, msg):
-        self.log(msg, "WARNING")
-
-    def warning(self, msg):
-        self.log(msg, "WARNING")
-
-    def error(self, msg):
-        self.log(msg, "ERROR")
-
-    def err(self, msg):
-        self.error(msg)
-
-    def critical(self, msg):
-        self.log(msg, "CRITICAL")

module_loader.py

@@ -21,11 +21,13 @@ Discover, load and manage Plinth modules
 
 import django
 import importlib
+import logging
 import os
 
-import cfg
 import urls
 
+LOGGER = logging.getLogger(__name__)
+
 
 def load_modules():
     """
@@ -37,15 +39,14 @@ def load_modules():
     for name in os.listdir('modules/enabled'):
         full_name = 'modules.{module}'.format(module=name)
 
-        cfg.log.info('Importing {full_name}'.format(full_name=full_name))
+        LOGGER.info('Importing %s', full_name)
         try:
             module = importlib.import_module(full_name)
             modules[name] = module
             module_names.append(name)
-        except ImportError as exception:
-            cfg.log.error(
-                'Could not import modules/{module}: {exception}'
-                .format(module=name, exception=exception))
+        except Exception as exception:
+            LOGGER.exception('Could not import modules/%s: %s',
+                             name, exception)
 
         _include_module_urls(full_name)
 
@@ -60,10 +61,10 @@ def load_modules():
             _insert_modules(module_name, module, remaining_modules,
                             ordered_modules)
         except KeyError:
-            cfg.log.error('Unsatified dependency for module - %s' %
-                          (module_name,))
+            LOGGER.error('Unsatified dependency for module - %s',
+                         module_name)
 
-    cfg.log.debug('Module load order - %s' % ordered_modules)
+    LOGGER.debug('Module load order - %s', ordered_modules)
 
     for module_name in ordered_modules:
         _initialize_module(modules[module_name])
@@ -87,8 +88,8 @@ def _insert_modules(module_name, module, remaining_modules, ordered_modules):
         try:
             module = remaining_modules.pop(dependency)
         except KeyError:
-            cfg.log.error('Not found or circular dependency - %s, %s' %
-                          (module_name, dependency))
+            LOGGER.error('Not found or circular dependency - %s, %s',
+                         module_name, dependency)
             raise
 
         _insert_modules(dependency, module, remaining_modules, ordered_modules)
@@ -104,7 +105,7 @@ def _include_module_urls(module_name):
             '', django.conf.urls.url(
                 r'', django.conf.urls.include(url_module)))
     except ImportError:
-        cfg.log.debug('No URLs for {module}'.format(module=module_name))
+        LOGGER.debug('No URLs for %s', module_name)
 
 
 def _initialize_module(module):
@@ -112,15 +113,14 @@ def _initialize_module(module):
     try:
         init = module.init
     except AttributeError:
-        cfg.log.debug('No init() for module - {module}'
-                      .format(module=module.__name__))
+        LOGGER.debug('No init() for module - %s', module.__name__)
         return
 
     try:
         init()
     except Exception as exception:
-        cfg.log.error('Exception while running init for {module}: {exception}'
-                      .format(module=module, exception=exception))
+        LOGGER.exception('Exception while running init for %s: %s',
+                         module, exception)
 
 
 def get_template_directories():
@@ -132,6 +132,4 @@ def get_template_directories():
     for name in os.listdir('modules/enabled'):
         directories.add(os.path.join('modules', name, 'templates'))
 
-    cfg.log.info('Template directories - %s' % directories)
-
     return directories

modules/config/config.py

@@ -25,6 +25,7 @@ from django.contrib.auth.decorators import login_required
 from django.core import validators
 from django.template.response import TemplateResponse
 from gettext import gettext as _
+import logging
 import re
 import socket
 
@@ -33,6 +34,9 @@ import cfg
 import util
 
 
+LOGGER = logging.getLogger(__name__)
+
+
 def get_hostname():
     """Return the hostname"""
     return socket.gethostname()
@@ -155,11 +159,11 @@ def set_hostname(hostname):
     # valid_hostname check, convert to ASCII.
     hostname = str(hostname)
 
-    cfg.log.info("Changing hostname to '%s'" % hostname)
+    LOGGER.info('Changing hostname to - %s', hostname)
     try:
-        actions.superuser_run("xmpp-pre-hostname-change")
-        actions.superuser_run("hostname-change", hostname)
-        actions.superuser_run("xmpp-hostname-change", hostname, async=True)
+        actions.superuser_run('xmpp-pre-hostname-change')
+        actions.superuser_run('hostname-change', hostname)
+        actions.superuser_run('xmpp-hostname-change', hostname, async=True)
     except OSError:
         return False
 

modules/firewall/firewall.py

@@ -22,12 +22,16 @@ Plinth module to configure a firewall
 from django.contrib.auth.decorators import login_required
 from django.template.response import TemplateResponse
 from gettext import gettext as _
+import logging
 
 import actions
 import cfg
 import service as service_module
 
 
+LOGGER = logging.getLogger(__name__)
+
+
 def init():
     """Initailze firewall module"""
     menu = cfg.main_menu.find('/sys')
@@ -99,7 +103,7 @@ def on_service_enabled(sender, service_id, enabled, **kwargs):
     internal_enabled_services = get_enabled_services(zone='internal')
     external_enabled_services = get_enabled_services(zone='external')
 
-    cfg.log.info('Service enabled - %s, %s' % (service_id, enabled))
+    LOGGER.info('Service enabled - %s, %s', service_id, enabled)
     service = service_module.SERVICES[service_id]
     for port in service.ports:
         if enabled:
@@ -137,8 +141,7 @@ def _run(arguments, superuser=False):
     """Run an given command and raise exception if there was an error"""
     command = 'firewall'
 
-    cfg.log.info('Running command - %s, %s, %s' % (command, arguments,
-                                                   superuser))
+    LOGGER.info('Running command - %s, %s, %s', command, arguments, superuser)
 
     if superuser:
         output, error = actions.superuser_run(command, arguments)

modules/pagekite/pagekite.py

@@ -27,11 +27,15 @@ from django.template import RequestContext
 from django.template.loader import render_to_string
 from django.template.response import TemplateResponse
 from gettext import gettext as _
+import logging
 
 import actions
 import cfg
 
 
+LOGGER = logging.getLogger(__name__)
+
+
 def init():
     """Intialize the PageKite module"""
     menu = cfg.main_menu.find('/apps')
@@ -130,7 +134,6 @@ def get_status():
 
     # Check if PageKite is installed
     output = _run(['get-installed'])
-    cfg.log('Output - %s' % output)
     if output.split()[0] != 'installed':
         return None
 
@@ -155,7 +158,7 @@ def get_status():
 
 def _apply_changes(request, old_status, new_status):
     """Apply the changes to PageKite configuration"""
-    cfg.log.info('New status is - %s' % new_status)
+    LOGGER.info('New status is - %s', new_status)
 
     if old_status != new_status:
         _run(['stop'])
@@ -194,8 +197,7 @@ def _run(arguments, superuser=True):
     """Run an given command and raise exception if there was an error"""
     command = 'pagekite-configure'
 
-    cfg.log.info('Running command - %s, %s, %s' % (command, arguments,
-                                                   superuser))
+    LOGGER.info('Running command - %s, %s, %s', command, arguments, superuser)
 
     if superuser:
         output, error = actions.superuser_run(command, arguments)

modules/users/users.py

@@ -7,11 +7,15 @@ from django.template import RequestContext
 from django.template.loader import render_to_string
 from django.template.response import TemplateResponse
 from gettext import gettext as _
+import logging
 
 import cfg
 from ..lib.auth import add_user
 
 
+LOGGER = logging.getLogger(__name__)
+
+
 def init():
     """Intialize the module"""
     menu = cfg.main_menu.find('/sys')
@@ -128,8 +132,7 @@ def _apply_edit_changes(request, data):
         username = field.split('delete_user_')[1]
 
         requesting_user = request.user.username
-        cfg.log.info('%s asked to delete %s' %
-                     (requesting_user, username))
+        LOGGER.info('%s asked to delete %s', requesting_user, username)
 
         if username == requesting_user:
             messages.error(

modules/xmpp/xmpp.py

@@ -5,12 +5,15 @@ from django.template import RequestContext
 from django.template.loader import render_to_string
 from django.template.response import TemplateResponse
 from gettext import gettext as _
+import logging
 
 import actions
 import cfg
 import service
 
 
+LOGGER = logging.getLogger(__name__)
+
 SIDE_MENU = {'title': _('XMPP'),
              'items': [{'url': '/apps/xmpp/configure',
                         'text': 'Configure XMPP Server'},
@@ -94,7 +97,7 @@ def get_status():
 
 def _apply_changes(request, old_status, new_status):
     """Apply the form changes"""
-    cfg.log.info('Status - %s, %s' % (old_status, new_status))
+    LOGGER.info('Status - %s, %s', old_status, new_status)
 
     if old_status['inband_enabled'] == new_status['inband_enabled']:
         messages.info(request, _('Setting unchanged'))
@@ -107,7 +110,7 @@ def _apply_changes(request, old_status, new_status):
         messages.success(request, _('Inband registration disabled'))
         option = 'noinband_enable'
 
-    cfg.log.info('Option - %s' % option)
+    LOGGER.info('Option - %s', option)
 
     _output, error = actions.superuser_run('xmpp-setup', [option])
     del _output  # Unused

plinth.py

@@ -4,6 +4,7 @@ import argparse
 import django.conf
 import django.core.management
 import django.core.wsgi
+import logging
 import os
 import stat
 import sys
@@ -16,9 +17,6 @@ import cfg
 import module_loader
 import service
 
-import logger
-from logger import Logger
-
 __version__ = "0.2.14"
 __author__ = "James Vasile"
 __copyright__ = "Copyright 2011-2013, James Vasile"
@@ -27,6 +25,8 @@ __maintainer__ = "James Vasile"
 __email__ = "james@jamesvasile.com"
 __status__ = "Development"
 
+LOGGER = logging.getLogger(__name__)
+
 
 def parse_arguments():
     """Parse command line arguments"""
@@ -54,8 +54,13 @@ def parse_arguments():
 
 def setup_logging():
     """Setup logging framework"""
-    cfg.log = Logger()
-    logger.init()
+    # Don't propagate cherrypy log messages to root logger
+    logging.getLogger('cherrypy').propagate = False
+
+    cherrypy.log.error_file = cfg.status_log_file
+    cherrypy.log.access_file = cfg.access_log_file
+    if not cfg.no_daemon:
+        cherrypy.log.screen = False
 
 
 def setup_paths():
@@ -67,6 +72,8 @@ def setup_paths():
 
 def setup_server():
     """Setup CherryPy server"""
+    LOGGER.info('Setting up CherryPy server')
+
     # Set the PID file path
     try:
         if cfg.pidfile:
@@ -129,6 +136,32 @@ def configure_django():
         'django.contrib.messages.context_processors.messages',
         'plinth.context_processor']
 
+    logging_configuration = {
+        'version': 1,
+        'disable_existing_loggers': False,
+        'formatters': {
+            'default': {
+                'format':
+                '[%(asctime)s] %(name)-14s %(levelname)-8s %(message)s',
+                }
+            },
+        'handlers': {
+            'file': {
+                'class': 'logging.FileHandler',
+                'filename': cfg.status_log_file,
+                'formatter': 'default'
+                },
+            'console': {
+                'class': 'logging.StreamHandler',
+                'formatter': 'default'
+                }
+            },
+        'root': {
+            'handlers': ['console', 'file'],
+            'level': 'DEBUG' if cfg.debug else 'INFO'
+            }
+        }
+
     data_file = os.path.join(cfg.data_dir, 'plinth.sqlite3')
 
     template_directories = module_loader.get_template_directories()
@@ -145,6 +178,7 @@ def configure_django():
                         'django.contrib.auth',
                         'django.contrib.contenttypes',
                         'django.contrib.messages'],
+        LOGGING=logging_configuration,
         LOGIN_URL=cfg.server_dir + '/accounts/login/',
         LOGIN_REDIRECT_URL=cfg.server_dir + '/',
         LOGOUT_URL=cfg.server_dir + '/accounts/logout/',
@@ -155,8 +189,11 @@ def configure_django():
         TEMPLATE_CONTEXT_PROCESSORS=context_processors,
         TEMPLATE_DIRS=template_directories)
 
+    LOGGER.info('Configured Django')
+    LOGGER.info('Template directories - %s', template_directories)
+
     if not os.path.isfile(data_file):
-        cfg.log.info('Creating and initializing data file')
+        LOGGER.info('Creating and initializing data file')
         django.core.management.call_command('syncdb', interactive=False)
         os.chmod(data_file, stat.S_IRUSR | stat.S_IWUSR | stat.S_IRGRP)
 

views.py

@@ -20,11 +20,15 @@ Main Plinth views
 """
 
 from django.http.response import HttpResponseRedirect
+import logging
 
 import cfg
 from withsqlite.withsqlite import sqlite_db
 
 
+LOGGER = logging.getLogger(__name__)
+
+
 def index(request):
     """Serve the main index page"""
     # TODO: Move firstboot handling to firstboot module somehow
@@ -36,7 +40,7 @@ def index(request):
             return HttpResponseRedirect(cfg.server_dir + '/firstboot')
 
         if database['state'] < 5:
-            cfg.log('First boot state = %d' % database['state'])
+            LOGGER.info('First boot state - %d', database['state'])
             return HttpResponseRedirect(
                 cfg.server_dir + '/firstboot/state%d' % database['state'])