add logging

README.md

@@ -62,3 +62,32 @@ auth:
       displayName: givenName
       email: mail
 ```
+
+###### Example 3
+
+This is a working example you can use to test things out. The settings use a public LDAP server.
+
+Find out more about this read-only public LDAP server:
+
+<http://www.forumsys.com/tutorials/integration-how-to/ldap/online-ldap-test-server/>
+
+```
+  ldap:
+    connect_settings:
+      url: ldap://ldap.forumsys.com
+    bind_options:
+      bindDN: cn=read-only-admin,dc=example,dc=com
+      bindCredentials: password
+    search:
+      base: dc=example,dc=com
+      opts:
+        scope: one # Base search (base), one level search (one) or subtree search (sub)
+        filter: (uid={{username}}) # Only {{username}} is available
+    field_mappings:
+      uid: uid # LDAP unique ID
+      username: uid # used for mention (@uid)
+      firstName: sn # Only surname is available, I think
+      lastName: sn
+      displayName: sn # Only surname is available, I think
+      email: mail
+```

lib/auth.js

@@ -1,11 +1,17 @@
 var fs = require('fs'),
     _ = require('lodash'),
+    util = require('util'),
+    format = util.format,
+    log4js = require('log4js'),
     mongoose = require('mongoose'),
     passport = require('passport'),
     ldap = require('ldapjs'),
-    LDAPStrategy = require('passport-ldapauth').Strategy;
+    LDAPStrategy = require('passport-ldapauth').Strategy,
+    logger = log4js.getLogger('lets-chat-ldap');
 
 function Ldap(options, core) {
+    logger.info('Initializing');
+
     this.options = options;
     this.core = core;
     this.key = 'ldap';
@@ -43,6 +49,7 @@ Ldap.key = 'ldap';
 
 Ldap.prototype.setup = function() {
     passport.use(this.getLdapStrategy());
+    logger.info('Registered');
 };
 
 Ldap.prototype.authenticate = function(req, cb) {
@@ -73,14 +80,19 @@ Ldap.prototype.getLdapStrategy = function() {
 
 Ldap.findOrCreateFromLDAP = function(options, core, ldapEntry, callback) {
     var User = mongoose.model('User');
+    var ldapUid = ldapEntry[options.field_mappings.uid]
+
+    logger.trace(format('Searching in database for User %s', ldapUid));
 
-    User.findOne({ uid: ldapEntry[options.field_mappings.uid] }, function (err, user) {
+    User.findOne({ uid: ldapUid }, function (err, user) {
         if (err) {
             return callback(err);
         }
         if (!user) {
+            logger.trace(format('User %s not found in database, creating new one', ldapUid));
             Ldap.createLdapUser(core, options, ldapEntry, callback);
         } else {
+            logger.trace(format('User %s found in database', ldapUid));
             return callback(null, user);
         }
     });
@@ -102,12 +114,13 @@ Ldap.createLdapUser = function(core, options, ldapEntry, callback) {
     if (!data.displayName) {
         data.displayName = data.firstName + ' ' + data.lastName;
     }
+    logger.trace(format('Attempting to add User %s to the database', data.uid));
 
     core.account.create(options.kerberos ? 'kerberos' : 'ldap',
                         data,
                         function (err, user) {
         if (err) {
-            console.error(err);
+            logger.error(err);
             return callback(err);
         }
         return callback(null, user);
@@ -136,37 +149,43 @@ Ldap.authorize = function(ldap_options, core, username, done) {
         }
 
         var client = ldap.createClient(options);
+        var bindDN = ldap_options.bind_options.bindDN;
+
+        logger.trace(format('Binding to %s', bindDN));
 
-        client.bind(ldap_options.bind_options.bindDN,
-            ldap_options.bind_options.bindCredentials,
+        client.bind(bindDN, ldap_options.bind_options.bindCredentials,
             function (err) {
 
             if (err) {
-                console.error(err);
+                logger.error('Error encounter on bind '+ err);
                 return done(err);
             }
 
+            logger.trace('Bind successful');
+
             var clientOpts = _.clone(ldap_options.search.opts);
 
             var filter = (clientOpts.filter || '')
                 .replace(/{{username}}/g, Ldap.sanitizeLDAP(username));
 
             clientOpts.filter = filter;
 
+            logger.trace(format('Searching for User %s', username));
+
             client.search(ldap_options.search.base,
                 clientOpts,
                 Ldap.getLdapSearchCallback(ldap_options, client, core, username, done));
         });
     } catch (err) {
-        console.error(err);
+        logger.error('Error encountered during authorization: ' + err);
         return done(err);
     }
 };
 
 Ldap.getLdapSearchCallback = function(options, client, core, username, done) {
     return function(err, res) {
         if (err) {
-            console.error(err);
+            logger.error('Error encountered during search: ' + err);
             return done(err);
         }
 
@@ -186,9 +205,12 @@ Ldap.getLdapSearchCallback = function(options, client, core, username, done) {
             if (result.status !== 0) {
                 var err = new Error('non-zero status from LDAP search: ' +
                 result.status);
+                logger.error('Unexpected result status from LDAP search: ' + result.status);
                 return done(err);
             }
 
+            logger.trace(format('Search for %s found %d users', username, foundUsers.length));
+
             switch (foundUsers.length) {
                 case 0:
                     return done();
@@ -203,6 +225,7 @@ Ldap.getLdapSearchCallback = function(options, client, core, username, done) {
             }
 
             if (!options.connect_settings.maxConnections) {
+                logger.trace('Unbinding');
                 client.unbind();
             }
         });

package.json

@@ -21,6 +21,7 @@
   },
   "peerDependencies": {
     "lodash": "^3.1.0",
+    "log4js": "~0.6.22",
     "mongoose": "~3.8.22",
     "passport": "^0.2.1"
   }