[JAVA-1803] Repeated connection with expected authentication errors is not deterministic Created: 06/May/15  Updated: 15/May/15  Resolved: 15/May/15

Status: Closed
Project: Java Driver
Component/s: None
Affects Version/s: 2.13.1
Fix Version/s: None

Type: Bug Priority: Major - P3
Reporter: Emmanuel Bernard Assignee: Unassigned
Resolution: Done Votes: 0
Labels: None
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified


 Description   

I found the following problem

// Mongo client with credentials on a non existing user
// we expect an auth failure error
MongoClient mongo = ...;
try {
    // this will raise an auth failure exception
    mongo.getDatabaseNames().contains( databaseName );
}
catch (MongoException me) {
    // auth failure exception, that's cool
}
 
try {
    // we try again to connect with the same credentials
    // we should get an auth failure
    db.collectionExists( "WeDoNotCareWhatItIsWeNeedToConnect" );
}
catch (MongoException me) {
    if ( me.getCode() == 18 ) { //AUTHENTICATION_FAILED_CODE
        System.out.println("Auth failure");
    }
    if ( me instanceof MongoTimeoutException ) {
        System.out.println("Timeout failure");
    }
}

This code without the thread sleep will raise a timeout exception. With the thread sleep (or with a debug/break point enforced), I get the expected auth failure.
Some kind of race condition is going on during the second connection attempt.

Retrying twice (i.e. on the third attempt to do db.collectionExists( "WeDoNotCareWhatItIsWeNeedToConnect" ); it works.

It might be related to JAVA-1780 but I don't know much about it. And trying the latest 2.13.2-SNAPSHOT did nto fix the issue



 Comments   
Comment by Jeffrey Yemin [ 15/May/15 ]

The baby is now closed.

Comment by Emmanuel Bernard [ 15/May/15 ]

Thanks Jeff.
No, all makes sense now. Let's close this baby.

Comment by Jeffrey Yemin [ 15/May/15 ]

Hi Emmanuel,

The server selection is not done in the background, but the server discovery and monitoring is. Without the Thread.sleep, there is not enough time for the server discovery to run to completion in the background before server selection in the foreground tims out. This is spelled out in gory detail in two specifications: Server Selection and Server Discovery and Monitoring.

Let me know if you have any further questions.

Comment by Emmanuel Bernard [ 15/May/15 ]

I think I understand, let me rephrase a bit to be sure.
Th driver does the server selection in the background. So if I don't put the Thread.sleep in between the two calls there is not enough time for a new server to be selected between the two calls. Correct?
If the server selection is done serially as part of each of my calls, I can't explain why the Thread.sleep in between makes any difference.

Note that the code passes with 2.12 but I guess in this version you don't have to do the server handshake to select the correct MongoCredential approach.

Here is the test with the Thread.sleep that makes it pass even if the timeout is at 200 or even 50ms.

package org.hibernate.ogm.datastore.mongodb.test.datastore;
 
import java.util.Arrays;
import java.util.List;
 
import com.mongodb.DB;
import com.mongodb.MongoClient;
import com.mongodb.MongoClientOptions;
import com.mongodb.MongoCredential;
import com.mongodb.MongoException;
import com.mongodb.ReadPreference;
import com.mongodb.ServerAddress;
import com.mongodb.WriteConcern;
import org.junit.Test;
 
import static org.junit.Assert.fail;
 
/**
 * The test expects a vanilla (i.e. without specific auth restriction) MongoDB database
 * running on 127.0.0.1 and port 27017
 */
public class MongoDBBugTest {
	private static final int AUTHENTICATION_FAILED_CODE = 18;
 
	@Test
	// This test fails for me and I expect it to pass
	public void testMongoDBAuthenticationWithoutExplicitSleep() throws Exception {
		MongoClientOptions.Builder optionsBuilder = new MongoClientOptions.Builder();
 
		optionsBuilder.connectTimeout( 50 );
		optionsBuilder.writeConcern( WriteConcern.ACKNOWLEDGED );
		optionsBuilder.readPreference( ReadPreference.primary() );
		MongoClientOptions clientOptions = optionsBuilder.build();
		List<MongoCredential> credentials = Arrays.asList(
				MongoCredential.createCredential(
						"notauser",
						"test",
						"test".toCharArray()
				)
		);
		ServerAddress serverAddress = new ServerAddress( "127.0.0.1", 27017 );
		MongoClient mongo = new MongoClient( serverAddress, credentials, clientOptions );
		Boolean containsDatabase;
		try {
			containsDatabase = mongo.getDatabaseNames().contains( "test" );
		}
		catch (MongoException me) {
			// we don't have enough privileges, ignore the database creation
			containsDatabase = null;
			switch ( me.getCode() ) {
				case AUTHENTICATION_FAILED_CODE:
					//success
					break;
				default:
					fail("Unexpected exception first " + me.getMessage());
			}
		}
		Thread.sleep( 1000 );
		DB db = mongo.getDB( "test" );
		try {
			db.collectionExists( "WeDoNotCareWhatItIsWeNeedToConnect" );
		}
		catch (MongoException me) {
			switch ( me.getCode() ) {
				case AUTHENTICATION_FAILED_CODE:
					//success
					break;
				default:
					fail("Unexpected exception " + me.getMessage());
			}
		}
	}
 
	@Test
	// This test passes for me
	public void testMongoDBAuthenticationWithExplicitSleep() throws Exception {
		MongoClientOptions.Builder optionsBuilder = new MongoClientOptions.Builder();
 
		optionsBuilder.connectTimeout( 200 );
		optionsBuilder.writeConcern( WriteConcern.ACKNOWLEDGED );
		optionsBuilder.readPreference( ReadPreference.primary() );
		MongoClientOptions clientOptions = optionsBuilder.build();
		List<MongoCredential> credentials = Arrays.asList(
				MongoCredential.createCredential(
						"notauser",
						"test",
						"test".toCharArray()
				)
		);
		ServerAddress serverAddress = new ServerAddress( "127.0.0.1", 27017 );
		MongoClient mongo = new MongoClient( serverAddress, credentials, clientOptions );
		Boolean containsDatabase;
		try {
			containsDatabase = mongo.getDatabaseNames().contains( "test" );
		}
		catch (MongoException me) {
			// we don't have enough privileges, ignore the database creation
			containsDatabase = null;
		}
		DB db = mongo.getDB( "test" );
		try {
			Thread.sleep( 500 );
			db.collectionExists( "WeDoNotCareWhatItIsWeNeedToConnect" );
		}
		catch (MongoException me) {
			switch ( me.getCode() ) {
				case AUTHENTICATION_FAILED_CODE:
					//success
					break;
				default:
					fail("Unexpected exception " + me.getMessage());
			}
		}
	}
}

Comment by Jeffrey Yemin [ 13/May/15 ]

Hi Emmanuel,

I understand now what's going on thanks to the test cases you provided. In the 2.x driver, the connect time stands in for a separate server selection timeout, and the driver uses it to determine how long to wait before giving up and throwing a MongoTimeoutException. The value you chose, 200 ms, is, for a localhost connection, right around the time it takes for the driver to connect to the server and call the commands it needs to call (buildInfo, isMaster) to determine what type of server it's talking to. The first call to getDatabaseNames gets in just under that 200 ms wire. The second call does not.

You can easily make both calls throw a MongoTimeoutException by shortening the connect timeout to something like 10 ms, and similarly, you can make both throw a CommandFailureException by lengthening the timeout to something like 1000 ms.

The design of the 2.x code base is going to make it hard to do anything different here. You should be aware, though, that starting with the 3.0 release the behavior is consistent, though likely not in the way that you would prefer: it always throws a MongoTimeoutException:

com.mongodb.MongoTimeoutException: Timed out after 200 ms while waiting for a server that matches 
ReadPreferenceServerSelector{readPreference=primary}.
Client view of cluster state is {type=UNKNOWN, 
servers=[{address=127.0.0.1:27017, type=UNKNOWN, state=CONNECTING, 
 exception={com.mongodb.MongoSecurityException: Exception authenticating MongoCredential{mechanism=null,   
 userName='notauser', source='test', password=<hidden>, mechanismProperties={}}}, 
 caused by {com.mongodb.MongoCommandException: Command failed with error 18: 'Authentication failed.' on server 127.0.0.1:27017. The full response is { "ok" : 0.0, "code" : 18, "errmsg" : "Authentication failed." }}}]

The reason is that in the 3.x code base authentication is part of the connection protocol, so the driver will not dole out a connection to a server that could not be authenticated against.

Comment by Emmanuel Bernard [ 08/May/15 ]

Hi Jeff, here is the test. It only requires MongoDB Driver 2.13.1 + JUnit as a dependency and a vanilla mongodb instance running on localhost.

package org.hibernate.ogm.datastore.mongodb.test.datastore;
 
import java.util.Arrays;
import java.util.List;
 
import com.mongodb.DB;
import com.mongodb.MongoClient;
import com.mongodb.MongoClientOptions;
import com.mongodb.MongoCredential;
import com.mongodb.MongoException;
import com.mongodb.ReadPreference;
import com.mongodb.ServerAddress;
import com.mongodb.WriteConcern;
import org.junit.Test;
 
import static org.junit.Assert.fail;
 
/**
 * The test expects a vanilla (i.e. without specific auth restriction) MongoDB database
 * running on 127.0.0.1 and port 27017
 */
public class MongoDBBugTest {
	private static final int AUTHENTICATION_FAILED_CODE = 18;
 
	@Test
	// This test fails for me and I expect it to pass
	public void testMongoDBAuthenticationWithoutExplicitSleep() throws Exception {
		MongoClientOptions.Builder optionsBuilder = new MongoClientOptions.Builder();
 
		optionsBuilder.connectTimeout( 200 );
		optionsBuilder.writeConcern( WriteConcern.ACKNOWLEDGED );
		optionsBuilder.readPreference( ReadPreference.primary() );
		MongoClientOptions clientOptions = optionsBuilder.build();
		List<MongoCredential> credentials = Arrays.asList(
				MongoCredential.createCredential(
						"notauser",
						"test",
						"test".toCharArray()
				)
		);
		ServerAddress serverAddress = new ServerAddress( "127.0.0.1", 27017 );
		MongoClient mongo = new MongoClient( serverAddress, credentials, clientOptions );
		Boolean containsDatabase;
		try {
			containsDatabase = mongo.getDatabaseNames().contains( "test" );
		}
		catch (MongoException me) {
			// we don't have enough privileges, ignore the database creation
			containsDatabase = null;
		}
		DB db = mongo.getDB( "test" );
		try {
			db.collectionExists( "WeDoNotCareWhatItIsWeNeedToConnect" );
		}
		catch (MongoException me) {
			switch ( me.getCode() ) {
				case AUTHENTICATION_FAILED_CODE:
					//success
					break;
				default:
					fail("Unexpected exception " + me.getMessage());
			}
		}
	}
 
	@Test
	// This test passes for me
	public void testMongoDBAuthenticationWithExplicitSleep() throws Exception {
		MongoClientOptions.Builder optionsBuilder = new MongoClientOptions.Builder();
 
		optionsBuilder.connectTimeout( 200 );
		optionsBuilder.writeConcern( WriteConcern.ACKNOWLEDGED );
		optionsBuilder.readPreference( ReadPreference.primary() );
		MongoClientOptions clientOptions = optionsBuilder.build();
		List<MongoCredential> credentials = Arrays.asList(
				MongoCredential.createCredential(
						"notauser",
						"test",
						"test".toCharArray()
				)
		);
		ServerAddress serverAddress = new ServerAddress( "127.0.0.1", 27017 );
		MongoClient mongo = new MongoClient( serverAddress, credentials, clientOptions );
		Boolean containsDatabase;
		try {
			containsDatabase = mongo.getDatabaseNames().contains( "test" );
		}
		catch (MongoException me) {
			// we don't have enough privileges, ignore the database creation
			containsDatabase = null;
		}
		DB db = mongo.getDB( "test" );
		try {
			Thread.sleep( 500 );
			db.collectionExists( "WeDoNotCareWhatItIsWeNeedToConnect" );
		}
		catch (MongoException me) {
			switch ( me.getCode() ) {
				case AUTHENTICATION_FAILED_CODE:
					//success
					break;
				default:
					fail("Unexpected exception " + me.getMessage());
			}
		}
	}
}

Comment by Emmanuel Bernard [ 07/May/15 ]

I get the timeout exception when I do not put any sleep. If I add a 250ms+ sleep then it works as expected. Let me try and write a running unit test tomorrow. I can reproduce it in Hibernate OGM but there is a lot of noise.

Comment by Jeffrey Yemin [ 07/May/15 ]

Hi Emmanuel,

I'm not yet able to reproduce this. What exactly are you doing to trigger the timeout exception? For me, I get an authentication failure both times. I tried it with a 5 second sleep before the first try block, and again with a five second sleep before the second try block.

Comment by Emmanuel Bernard [ 06/May/15 ]

Oops, sorry for the crappy title :/
It should be something like: "Repeated connection with expected authentication errors is not undeterministic"

Generated at Thu Feb 08 08:55:32 UTC 2024 using Jira 9.7.1#970001-sha1:2222b88b221c4928ef0de3161136cc90c8356a66.