From 6780e91351915bf0a020c93cae67d597c406c348 Mon Sep 17 00:00:00 2001
From: David Read <david.read@hackneyworkshop.com>
Date: Fri, 15 Jun 2012 13:46:04 +0100
Subject: [PATCH] Improve logging in useful places.

---
 ckan/controllers/package.py |  2 ++
 ckan/lib/authenticator.py   |  6 ++++++
 ckan/lib/base.py            |  3 +++
 ckan/lib/search/__init__.py | 13 +++++++------
 4 files changed, 18 insertions(+), 6 deletions(-)

diff --git a/ckan/controllers/package.py b/ckan/controllers/package.py
index 9403a0271e3..a7df2cf1849 100644
--- a/ckan/controllers/package.py
+++ b/ckan/controllers/package.py
@@ -592,6 +592,8 @@ def _save_new(self, context, package_type=None):
 
     def _save_edit(self, name_or_id, context):
         from ckan.lib.search import SearchIndexError
+        log.debug('Package save request name: %s POST: %r',
+                  name_or_id, request.POST)
         try:
             data_dict = clean_dict(unflatten(
                 tuplize_dict(parse_params(request.POST))))
diff --git a/ckan/lib/authenticator.py b/ckan/lib/authenticator.py
index b56711a3427..6f061caad91 100644
--- a/ckan/lib/authenticator.py
+++ b/ckan/lib/authenticator.py
@@ -1,8 +1,12 @@
+import logging
+
 from zope.interface import implements
 from repoze.who.interfaces import IAuthenticator
 
 from ckan.model import User, Session
 
+log = logging.getLogger(__name__)
+
 class OpenIDAuthenticator(object):
     implements(IAuthenticator)
 
@@ -25,8 +29,10 @@ def authenticate(self, environ, identity):
             return None
         user = User.by_name(identity.get('login'))
         if user is None:
+            log.debug('Login failed - username %r not found', identity.get('login'))
             return None
         if user.validate_password(identity.get('password')):
             return user.name
+        log.debug('Login as %r failed - password not valid', identity.get('login'))
         return None
 
diff --git a/ckan/lib/base.py b/ckan/lib/base.py
index f2cc447fdea..52604d48e7f 100644
--- a/ckan/lib/base.py
+++ b/ckan/lib/base.py
@@ -29,6 +29,8 @@
 from ckan.lib.helpers import json
 import ckan.model as model
 
+log = logging.getLogger(__name__)
+
 PAGINATE_ITEMS_PER_PAGE = 50
 
 APIKEY_HEADER_NAME_KEY = 'apikey_header_name'
@@ -139,6 +141,7 @@ def render_template():
         response.headers["Cache-Control"] = "private"
         # Prevent any further rendering from being cached.
         request.environ['__no_cache__'] = True
+    log.debug('Template cache-control: %s' % response.headers["Cache-Control"])
 
     # Render Time :)
     try:
diff --git a/ckan/lib/search/__init__.py b/ckan/lib/search/__init__.py
index abc78b798fd..b68e7850c47 100644
--- a/ckan/lib/search/__init__.py
+++ b/ckan/lib/search/__init__.py
@@ -128,11 +128,11 @@ def rebuild(package_id=None,only_missing=False,force=False,refresh=False):
         If a dataset id is provided, only this dataset will be reindexed.
         When reindexing all datasets, if only_missing is True, only the
         datasets not already indexed will be processed. If force equals
-        True, if an execption is found, the exception will be logged, but
+        True, if an exception is found, the exception will be logged, but
         the process will carry on.
     '''
     from ckan import model
-    log.debug("Rebuilding search index...")
+    log.info("Rebuilding search index...")
 
     package_index = index_for(model.Package)
 
@@ -140,21 +140,22 @@ def rebuild(package_id=None,only_missing=False,force=False,refresh=False):
         pkg_dict = get_action('package_show')(
                     {'model': model, 'ignore_auth': True, 'validate': False},
                     {'id': package_id})
+        log.info('Indexing just package %r...', pkg_dict['name'])
         package_index.remove_dict(pkg_dict)
         package_index.insert_dict(pkg_dict)
     else:
         package_ids = [r[0] for r in model.Session.query(model.Package.id).filter(model.Package.state == 'active').all()]
         if only_missing:
-            log.debug('Indexing only missing packages...')
+            log.info('Indexing only missing packages...')
             package_query = query_for(model.Package)
             indexed_pkg_ids = set(package_query.get_all_entity_ids(max_results=len(package_ids)))
             package_ids = set(package_ids) - indexed_pkg_ids     # Packages not indexed
 
             if len(package_ids) == 0:
-                log.debug('All datasets are already indexed')
+                log.info('All datasets are already indexed')
                 return
         else:
-            log.debug('Rebuilding the whole index...')
+            log.info('Rebuilding the whole index...')
             # When refreshing, the index is not previously cleared
             if not refresh:
                 package_index.clear()
@@ -176,7 +177,7 @@ def rebuild(package_id=None,only_missing=False,force=False,refresh=False):
                     raise
 
     model.Session.commit()
-    log.debug('Finished rebuilding search index.')
+    log.info('Finished rebuilding search index.')
 
 def check():
     from ckan import model