JAVA-785: Improve logging for socket connect, read, and write. As part of this "can't say/call something is gone for good and replaced with something more understandable.

Also fixed the retry log message to properly report elapsed time, and changed it from severe to warning.  As part of this, restructured the code to make it more intelligible.

Author: jyemin

src/main/com/mongodb/DBPort.java

@@ -202,8 +202,7 @@ public synchronized void ensureOpen()
         _open();
     }
 
-    boolean _open()
-        throws IOException {
+    void _open() throws IOException {
 
         long sleepTime = 100;
 
@@ -212,11 +211,9 @@ boolean _open()
             maxAutoConnectRetryTime = _options.maxAutoConnectRetryTime;
         }
 
+        boolean successfullyConnected = false;
         final long start = System.currentTimeMillis();
-        while ( true ){
-            
-            IOException lastError = null;
-
+        do {
             try {
                 _socket = _options.socketFactory.createSocket();
                 _socket.connect( _addr , _options.connectTimeout );
@@ -226,30 +223,28 @@ boolean _open()
                 _socket.setSoTimeout( _options.socketTimeout );
                 _in = new BufferedInputStream( _socket.getInputStream() );
                 _out = _socket.getOutputStream();
-                return true;
+                successfullyConnected = true;
             }
-            catch ( IOException ioe ){
-                lastError = new IOException( "couldn't connect to [" + _addr + "] bc:" + ioe );
-                _logger.log( Level.INFO , "connect fail to : " + _addr , ioe );
+            catch ( IOException e ){
                 close();
-            }
-            
-            if ( ! _options.autoConnectRetry || ( _pool != null && ! _pool._everWorked ) )
-                throw lastError;
-            
-            long sleptSoFar = System.currentTimeMillis() - start;
 
-            if ( sleptSoFar >= maxAutoConnectRetryTime )
-                throw lastError;
-            
-            if ( sleepTime + sleptSoFar > maxAutoConnectRetryTime )
-                sleepTime = maxAutoConnectRetryTime - sleptSoFar;
+                if (!_options.autoConnectRetry || (_pool != null && !_pool._everWorked))
+                    throw e;
 
-            _logger.severe( "going to sleep and retry.  total sleep time after = " + ( sleptSoFar + sleptSoFar ) + "ms  this time:" + sleepTime + "ms" );
-            ThreadUtil.sleep( sleepTime );
-            sleepTime *= 2;
-            
-        }
+                long waitSoFar = System.currentTimeMillis() - start;
+
+                if (waitSoFar >= maxAutoConnectRetryTime)
+                    throw e;
+
+                if (sleepTime + waitSoFar > maxAutoConnectRetryTime)
+                    sleepTime = maxAutoConnectRetryTime - waitSoFar;
+
+                _logger.log(Level.WARNING, "Exception connecting to " + serverAddress().getHost() + ": " + e +
+                        ".  Total wait time so far is " + waitSoFar + " ms.  Will retry after sleeping for " + sleepTime + " ms.");
+                ThreadUtil.sleep(sleepTime);
+                sleepTime *= 2;
+            }
+        } while (!successfullyConnected);
     }
 
     @Override

src/main/com/mongodb/DBTCPConnector.java

@@ -150,7 +150,7 @@ public WriteResult say( DB db , OutMessage m , WriteConcern concern , ServerAddr
             _error( ioe, false );
 
             if ( concern.raiseNetworkErrors() )
-                throw new MongoException.Network( "can't say something" , ioe );
+                throw new MongoException.Network("Write operation to server " + port.host() + " failed on database " + db , ioe );
 
             CommandResult res = new CommandResult(port.serverAddress());
             res.put( "ok" , false );
@@ -250,8 +250,7 @@ private Response innerCall(final DB db, final DBCollection coll, final OutMessag
             retry = retries > 0 && !coll._name.equals( "$cmd" )
                     && !(ioe instanceof SocketTimeoutException) && _error( ioe, secondaryOk );
             if ( !retry ){
-                throw new MongoException.Network( "can't call something : " + port.host() + "/" + db,
-                                                  ioe );
+                throw  new MongoException.Network("Read operation to server " + port.host() + " failed on database " + db , ioe );
             }
         }
         catch ( RuntimeException re ){

src/test/com/mongodb/DBPortTest.java

@@ -21,6 +21,7 @@
 import org.testng.annotations.Test;
 
 import java.io.IOException;
+import java.net.UnknownHostException;
 import java.util.HashSet;
 import java.util.Set;
 
@@ -68,4 +69,23 @@ public void testAuthentication() throws IOException {
         }
     }
 
+    @Test
+    public void testOpenFailure() throws UnknownHostException {
+        final MongoOptions options = new MongoOptions();
+        options.autoConnectRetry = true;
+        options.maxAutoConnectRetryTime = 350;
+
+        final DBPortPool portPool = new DBPortPool(new ServerAddress("localhost", 50051), options);
+        portPool._everWorked = true;
+
+        DBPort port = new DBPort(new ServerAddress("localhost", 50051), portPool, options);
+        try {
+            port._open();
+            fail("Open should fail");
+        } catch (IOException e) {
+            // should get exception
+        }
+
+    }
+
 }