MSSQL Server logs Prelogin Warning as part of wait strategy implementation

[marvinosswald]

i get prelogin warning messages after container boot, but it eventually stops and my sql import script runs just fine.
Afterwards the rest of my test runs perfectly, i'd just like to know how i could wait for something or improve this behaviour in anyway.

Aug 06, 2020 9:17:30 AM com.microsoft.sqlserver.jdbc.SQLServerConnection Prelogin
WARNING: ConnectionID:1 ClientConnectionId: e4e44c35-9473-4c70-ab46-24f526599b5c Prelogin error: host localhost port 32787 Unexpected end of prelogin response after 0 bytes read
Aug 06, 2020 9:17:30 AM com.microsoft.sqlserver.jdbc.SQLServerConnection Prelogin
WARNING: ConnectionID:1 ClientConnectionId: 808607de-dc0c-45b4-bbde-c03e310426d8 Prelogin error: host localhost port 32787 Unexpected end of prelogin response after 0 bytes read
Aug 06, 2020 9:17:31 AM com.microsoft.sqlserver.jdbc.SQLServerConnection Prelogin
WARNING: ConnectionID:1 ClientConnectionId: 6b866882-e0c2-4a93-82d7-5261dc061492 Prelogin error: host localhost port 32787 Unexpected end of prelogin response after 0 bytes read
Aug 06, 2020 9:17:31 AM com.microsoft.sqlserver.jdbc.SQLServerConnection Prelogin
WARNING: ConnectionID:1 ClientConnectionId: d85f4d62-45b0-4b40-b601-a24a2bb3f48e Prelogin error: host localhost port 32787 Unexpected end of prelogin response after 0 bytes read
Aug 06, 2020 9:17:32 AM com.microsoft.sqlserver.jdbc.SQLServerConnection Prelogin
WARNING: ConnectionID:1 ClientConnectionId: 01370df2-2393-4888-8e98-6b2cd8a335e0 Prelogin error: host localhost port 32787 Unexpected end of prelogin response after 0 bytes read
Aug 06, 2020 9:17:33 AM com.microsoft.sqlserver.jdbc.SQLServerConnection Prelogin
WARNING: ConnectionID:1 ClientConnectionId: c57ee0b6-b86c-4a77-a82c-d72e82072595 Prelogin error: host localhost port 32787 Unexpected end of prelogin response after 0 bytes read
Aug 06, 2020 9:17:34 AM com.microsoft.sqlserver.jdbc.SQLServerConnection Prelogin
WARNING: ConnectionID:1 ClientConnectionId: 374d4277-fcd2-4684-a080-ba2c20b91ee7 Prelogin error: host localhost port 32787 Unexpected end of prelogin response after 0 bytes read

This is my extended MssqlContainer, i've tried adding a line to wait for a specific log line but it doesn't seem to make any difference.

public class MyMSSQLContainer extends MSSQLServerContainer<MyMSSQLContainer> {
	private static final String IMAGE_VERSION = "mcr.microsoft.com/mssql/server:2017-CU12";
	private static MyMSSQLContainer container;

	private MyMSSQLContainer() {
		super(IMAGE_VERSION);
	}

	public static MyMSSQLContainer getInstance() {
		if (container == null) {
			container = new MyMSSQLContainer().waitingFor(Wait.forLogMessage("*SQL Server is now ready for client connections*", 1));
		}
		return container;
	}

	@Override
	public void start() {
		super.start();
	}

	@Override
	public void stop() {
		//do nothing, JVM handles shut down
	}
}

This is my base test class where i init the container and run the schema and data init script..

public abstract class AbstractApiTest {
	//for ci testing: https://www.testcontainers.org/supported_docker_environment/continuous_integration/bitbucket_pipelines/
	public static MSSQLServerContainer<MyMSSQLContainer> mssqlServerContainer = MyMSSQLContainer.getInstance();

	@Autowired
	MockMvc mockMvc;

	@Autowired
	ObjectMapper objectMapper;

	static {
		mssqlServerContainer.start();
		ScriptUtils.runInitScript(new JdbcDatabaseDelegate(mssqlServerContainer, ""), "setup.sql");
	}

	static class Initializer implements ApplicationContextInitializer<ConfigurableApplicationContext> {

		public void initialize(ConfigurableApplicationContext configurableApplicationContext) {
			TestPropertyValues
				.of(
					"spring.datasource.url=" + mssqlServerContainer.getJdbcUrl(),
					"spring.datasource.username=" + mssqlServerContainer.getUsername(),
					"spring.datasource.password=" + mssqlServerContainer.getPassword()
				)
				.applyTo(configurableApplicationContext.getEnvironment());
		}
	}
}

[stale]

This issue has been automatically marked as stale because it has not had recent activity. It will be closed if no further activity occurs. If you believe this is a mistake, please reply to this comment to keep it open. If there isn't one already, a PR to fix or at least reproduce the problem in a test case will always help us get back on track to tackle this.

[franklsm1]

Seeing this same issue as well, when using a r2dbc connection.

[AB-xdev]

This problem seems to come from the mssql-jdbc-driver directly:
https://github.com/microsoft/mssql-jdbc/blob/0f3e0a10f2f85b5b357811907fdb487d63e49830/src/main/java/com/microsoft/sqlserver/jdbc/SQLServerConnection.java#L3107-L3118

[rnorth]

Hmm, I've not had a chance to dig into this, but it sounds like there's a log warning being emitted when Testcontainers is testing the JDBC connection while the container is starting.

Is the problem just log spam, or is there some other problem?

[AB-xdev]

I think it's just log spam (however I'm not 100% sure) looks like the port is exposed but the SQL Server is not fully setup / starting.
After the container/server says Server is listening on [ ... ] the warning is gone in our tests.

[tsmets]

I have a similar issue here :

[csolem]

Same here with version 1.16.2. A hacky workaround that avoids the warnings in our case:

new MSSQLServerContainer<>("mcr.microsoft.com/mssql/server:2017-latest")
      .withStartupCheckStrategy(new MinimumDurationRunningStartupCheckStrategy(Duration.ofSeconds(5)));

[namgaxilem]

Still getting this issue, the insert and select still successful but still get warning and throw SQLException in Spring RestController:

@GetMapping("/v1/user-request/")
public String getUserRequest(@RequestParam Long id) throws SQLException {
    Optional<UserRequest> list = userRequestRepository.findById(id);
    return list.get().getData();
}

[Danielliudov]

I am experiencing the same issue is there any resolution to it?

[anderso]

Same here, annoying stderr messages logged while container is starting up. I believe this loop executing the test query is triggering it:

testcontainers-java/modules/jdbc/src/main/java/org/testcontainers/containers/JdbcDatabaseContainer.java

Lines 142 to 182 in b50cfee

	protected void waitUntilContainerStarted() {
	logger()
	.info(
	"Waiting for database connection to become available at {} using query '{}'",
	getJdbcUrl(),
	getTestQueryString()
	);
	// Repeatedly try and open a connection to the DB and execute a test query
	long start = System.currentTimeMillis();
	Exception lastConnectionException = null;
	while (System.currentTimeMillis() < start + (1000 * startupTimeoutSeconds)) {
	if (!isRunning()) {
	Thread.sleep(100L);
	} else {
	try (Connection connection = createConnection(""); Statement statement = connection.createStatement()) {
	boolean testQuerySucceeded = statement.execute(this.getTestQueryString());
	if (testQuerySucceeded) {
	return;
	}
	} catch (NoDriverFoundException e) {
	// we explicitly want this exception to fail fast without retries
	throw e;
	} catch (Exception e) {
	lastConnectionException = e;
	// ignore so that we can try again
	logger().debug("Failure when trying test query", e);
	Thread.sleep(100L);
	}
	}
	}
	throw new IllegalStateException(
	String.format(
	"Container is started, but cannot be accessed by (JDBC URL: %s), please check container logs",
	this.getJdbcUrl()
	),
	lastConnectionException
	);
	}

[zahidzia]

Any updates on how to fix this annoying log spam?

[anderso]

The mssql jdbc driver is logging with java util logging to the logger named com.microsoft.sqlserver.jdbc.Connection

https://github.com/microsoft/mssql-jdbc/blob/0f3e0a10f2f85b5b357811907fdb487d63e49830/src/main/java/com/microsoft/sqlserver/jdbc/SQLServerConnection.java#L1213-L1214

So the easiest way to disable it would be disable the warning level of this logger, how to do it depends on your logging setup.

Another alternative would be to override waitUntilContainerStarted, the question is what to replace it with, is there an alternative way to check if mssql has started? This code is common for all jdbc containers so I'm guessing only the mssql driver logs this as warning or this would have been fixed by now.

Another alternative is to wait for a while so that when this method is called the database should already be up, as suggested above.