SPY-157: Add Auth logging.

Motivation
----------
Debugging how long authentication steps take is currently not
possible. Proper logging needs to be added in order to debug
authentication timeframes.

Modifications
-------------
Added logging infrastructure for the individual steps (list sasl
mechs, and challenge/response cycles), as well as a total amount
on a per-node basis.

If an individual step takes over 250ms it is WARNed instead of
DEBUGed, and if the total auth step takes over 1 second it it also
WARNed. Note that while these timings are fixed values, in general
the operation taking this long points to something wrong since it
is expected to take in the 1ms range.

Result
------
Auth times can now be observed both in development and production,
better pointing to possible issues.

Change-Id: I3deab53332251263c5a6dcf3e2bfd75538dfb24c
Reviewed-on: http://review.couchbase.org/34849
Reviewed-by: Matt Ingenthron <matt@couchbase.com>
Tested-by: Michael Nitschinger <michael.nitschinger@couchbase.com>

Author: daschl

src/main/java/net/spy/memcached/auth/AuthThread.java

@@ -1,6 +1,6 @@
 /**
  * Copyright (C) 2006-2009 Dustin Sallings
- * Copyright (C) 2009-2013 Couchbase, Inc.
+ * Copyright (C) 2009-2014 Couchbase, Inc.
  *
  * Permission is hereby granted, free of charge, to any person obtaining a copy
  * of this software and associated documentation files (the "Software"), to deal
@@ -32,6 +32,7 @@
 import net.spy.memcached.MemcachedNode;
 import net.spy.memcached.OperationFactory;
 import net.spy.memcached.compat.SpyThread;
+import net.spy.memcached.compat.log.Level;
 import net.spy.memcached.ops.Operation;
 import net.spy.memcached.ops.OperationCallback;
 import net.spy.memcached.ops.OperationStatus;
@@ -41,6 +42,18 @@
  */
 public class AuthThread extends SpyThread {
 
+  /**
+   * If a SASL step takes longer than this period in milliseconds, a warning
+   * will be issued instead of a debug message.
+   */
+  public static final int AUTH_ROUNDTRIP_THRESHOLD = 250;
+
+  /**
+   * If the total AUTH steps take longer than this period in milliseconds, a
+   * warning will be issued instead of a debug message.
+   */
+  public static final int AUTH_TOTAL_THRESHOLD = 1000;
+
   public static final String MECH_SEPARATOR = " ";
 
   private final MemcachedConnection conn;
@@ -108,17 +121,26 @@ public void complete() {
   @Override
   public void run() {
     final AtomicBoolean done = new AtomicBoolean();
+    long totalStart = System.nanoTime();
 
     String[] supportedMechs;
+    long mechsStart = System.nanoTime();
     if (authDescriptor.getMechs() == null
       || authDescriptor.getMechs().length == 0) {
       supportedMechs = listSupportedSASLMechanisms(done);
     } else {
       supportedMechs = authDescriptor.getMechs();
     }
+    long mechsDiff = System.nanoTime() - mechsStart;
+    String msg = String.format("SASL List Mechanisms took %dms on %s",
+      mechsDiff, node.toString());
+    Level level = mechsDiff
+      >= AUTH_ROUNDTRIP_THRESHOLD ? Level.WARN : Level.DEBUG;
+    getLogger().log(level, msg);
 
     OperationStatus priorStatus = null;
     while (!done.get()) {
+      long stepStart = System.nanoTime();
       final CountDownLatch latch = new CountDownLatch(1);
       final AtomicReference<OperationStatus> foundStatus =
         new AtomicReference<OperationStatus>();
@@ -163,6 +185,13 @@ public void complete() {
           op.cancel();
         }
         done.set(true); // If we were interrupted, tear down.
+      } finally {
+        long stepDiff = System.nanoTime() - stepStart;
+        msg = String.format("SASL Step took %dms on %s",
+          stepDiff, node.toString());
+        level = mechsDiff
+          >= AUTH_ROUNDTRIP_THRESHOLD ? Level.WARN : Level.DEBUG;
+        getLogger().log(level, msg);
       }
 
       // Get the new status to inspect it.
@@ -174,6 +203,12 @@ public void complete() {
         }
       }
     }
+
+    long totalDiff = System.nanoTime() - totalStart;
+    msg = String.format("SASL Auth took %dms on %s",
+      totalDiff, node.toString());
+    level = mechsDiff >= AUTH_TOTAL_THRESHOLD ? Level.WARN : Level.DEBUG;
+    getLogger().log(level, msg);
   }
 
   private Operation buildOperation(OperationStatus st, OperationCallback cb,