Login Failed for user during Migrate() on Azure. Error number: 18456

[programista25]

Cannot perform migration on Azure SQL Database using EF Core randomly due to following exception:

**Exception message**: System.Data.SqlClient.SqlException (0x80131904): Login failed for user 'admin'.
**Error Number**: 18456
**State**: 1
**Class**: 14
**Stack trace**: at System.Data.SqlClient.SqlInternalConnectionTds..ctor(DbConnectionPoolIdentity identity, SqlConnectionString connectionOptions, SqlCredential credential, Object providerInfo, String newPassword, SecureString newSecurePassword, Boolean redirectedUserInstance, SqlConnectionString userConnectionOptions, SessionData reconnectSessionData, Boolean applyTransientFaultHandling, String accessToken)
2019-05-07T09:18:18.1797251Z    at System.Data.SqlClient.SqlConnectionFactory.CreateConnection(DbConnectionOptions options, DbConnectionPoolKey poolKey, Object poolGroupProviderInfo, DbConnectionPool pool, DbConnection owningConnection, DbConnectionOptions userOptions)
2019-05-07T09:18:18.1797779Z    at System.Data.ProviderBase.DbConnectionFactory.CreatePooledConnection(DbConnectionPool pool, DbConnection owningObject, DbConnectionOptions options, DbConnectionPoolKey poolKey, DbConnectionOptions userOptions)
2019-05-07T09:18:18.1798222Z    at System.Data.ProviderBase.DbConnectionPool.CreateObject(DbConnection owningObject, DbConnectionOptions userOptions, DbConnectionInternal oldConnection)
2019-05-07T09:18:18.1798546Z    at System.Data.ProviderBase.DbConnectionPool.UserCreateRequest(DbConnection owningObject, DbConnectionOptions userOptions, DbConnectionInternal oldConnection)
2019-05-07T09:18:18.1799015Z    at System.Data.ProviderBase.DbConnectionPool.TryGetConnection(DbConnection owningObject, UInt32 waitForMultipleObjectsTimeout, Boolean allowCreate, Boolean onlyOneCheckConnection, DbConnectionOptions userOptions, DbConnectionInternal& connection)
2019-05-07T09:18:18.1799424Z    at System.Data.ProviderBase.DbConnectionPool.TryGetConnection(DbConnection owningObject, TaskCompletionSource`1 retry, DbConnectionOptions userOptions, DbConnectionInternal& connection)
2019-05-07T09:18:18.1799897Z    at System.Data.ProviderBase.DbConnectionFactory.TryGetConnection(DbConnection owningConnection, TaskCompletionSource`1 retry, DbConnectionOptions userOptions, DbConnectionInternal oldConnection, DbConnectionInternal& connection)
2019-05-07T09:18:18.1800863Z    at System.Data.ProviderBase.DbConnectionInternal.TryOpenConnectionInternal(DbConnection outerConnection, DbConnectionFactory connectionFactory, TaskCompletionSource`1 retry, DbConnectionOptions userOptions)
2019-05-07T09:18:18.1802601Z    at System.Data.SqlClient.SqlConnection.TryOpen(TaskCompletionSource`1 retry)
2019-05-07T09:18:18.1802906Z    at System.Data.SqlClient.SqlConnection.Open()
2019-05-07T09:18:18.1803225Z    at Microsoft.EntityFrameworkCore.Storage.RelationalConnection.OpenDbConnection(Boolean errorsExpected)
2019-05-07T09:18:18.1803519Z    at Microsoft.EntityFrameworkCore.Storage.RelationalConnection.Open(Boolean errorsExpected)
2019-05-07T09:18:18.1803814Z    at Microsoft.EntityFrameworkCore.SqlServer.Storage.Internal.SqlServerDatabaseCreator.<>c__DisplayClass18_0.<Exists>b__0(DateTime giveUp)
2019-05-07T09:18:18.1804141Z    at Microsoft.EntityFrameworkCore.ExecutionStrategyExtensions.<>c__DisplayClass12_0`2.<Execute>b__0(DbContext c, TState s)
2019-05-07T09:18:18.1804455Z    at Microsoft.EntityFrameworkCore.Storage.ExecutionStrategy.ExecuteImplementation[TState,TResult](Func`3 operation, Func`3 verifySucceeded, TState state)
2019-05-07T09:18:18.1804761Z    at Microsoft.EntityFrameworkCore.Storage.ExecutionStrategy.Execute[TState,TResult](TState state, Func`3 operation, Func`3 verifySucceeded)
2019-05-07T09:18:18.1805084Z    at Microsoft.EntityFrameworkCore.ExecutionStrategyExtensions.Execute[TState,TResult](IExecutionStrategy strategy, Func`2 operation, Func`2 verifySucceeded, TState state)
2019-05-07T09:18:18.1805378Z    at Microsoft.EntityFrameworkCore.Migrations.HistoryRepository.Exists()
2019-05-07T09:18:18.1805690Z    at Microsoft.EntityFrameworkCore.Migrations.Internal.Migrator.Migrate(String targetMigration)
2019-05-07T09:18:18.1805993Z    at Apport.Application.Migrator.Program.MigrateDatabase[TDbContext](IServiceProvider serviceProvider)

Steps to reproduce

I performed following code against Azure SQL database:

var migrator = dbContext.GetService<IMigrator>();
migrator.Migrate();

This code also causes an exception:

dbContext.Database.Migrate();

Further technical details

EF Core version: 2.2.2 Database Provider: Microsoft.EntityFrameworkCore.SqlServer Operating system: Windows 10 IDE: Visual Studio 2017 15.4

My investigations

In file SqlServerDatabaseCreator following method does not contains error number 18456:

// Login failed is thrown when database does not exist (See Issue #776)
// Unable to attach database file is thrown when file does not exist (See Issue #2810)
// Unable to open the physical file is thrown when file does not exist (See Issue #2810)
private static bool IsDoesNotExist(SqlException exception) =>
    exception.Number == 4060 || exception.Number == 1832 || exception.Number == 5120;

As well as in this method:

private bool RetryOnExistsFailure(SqlException exception)
{           
      if (exception.Number == 233
           || exception.Number == -2
           || exception.Number == 4060
           || exception.Number == 1832
           || exception.Number == 5120)
       {
           ClearPool();
           return true;
       }

       return false;
}

But it can be some wrong error number returned from Azure

[ErikEJ]

18456 means invalid credentials: https://docs.microsoft.com/en-us/sql/relational-databases/errors-events/mssqlserver-18456-database-engine-error?view=sql-server-2017

[programista25]

Credentials are ok - I'm sure of it. The problem is that bug occurs randomly. I can connect to master db using same connection string. Notice, that I'm using Azure SQL Server. If the credentials will be invalid, State in the exception will has number higher than 1.

[ajcvickers]

@programista25 This looks like an issue with the underlying SqlClient ADO.NET provider, since that is the component that is connecting to the database. I'll move it to the corefx repo unless there is any reason to think this is EF-specific.

[programista25]

I did a little bit more investigation using this class: EFCore.Relational/Migrations/Internal/Migrator.cs.

I've added CustomMigrate method which is refactored from the original one:

public virtual void Migrate(string targetMigration = null)
{
    _logger.MigrateUsingConnection(this, _connection);

    if (!_historyRepository.Exists())
    {
         if (!_databaseCreator.Exists())
         {
             _databaseCreator.Create();
         }

         var command = _rawSqlCommandBuilder.Build(_historyRepository.GetCreateScript());
         command.ExecuteNonQuery(_connection);
    }

    var commandLists = GetMigrationCommandLists(_historyRepository.GetAppliedMigrations(), targetMigration);
    foreach (var commandList in commandLists)
    {
         _migrationCommandExecutor.ExecuteNonQuery(commandList(), _connection);
    }
}

I think, that _databaseCreator.Exists() method is doing the check in wrong way. Shouldn't it use connection to master db and check whether db exists and if not create it with this SQL?:

IF NOT EXISTS (SELECT * FROM sys.databases WHERE name = 'database')
BEGIN
    CREATE DATABASE database
END"

I've refactored it and my CustomMigratemethod looks like following:

public virtual void CustomMigrate(DbContext masterDbContext, ConnectionConfiguration connection)
{
    //connection param contains connection string to db which we want to migrate
    var database = connection.InitialCatalog;

    var createSql = $@"IF NOT EXISTS (SELECT * FROM sys.databases WHERE name = '{database}')
                     BEGIN
                        CREATE DATABASE {database}
                     END";
    masterDbContext.Database.ExecuteSqlCommand(new RawSqlString(createSql));
    //Everything above is working fine

    //Problem starts below, in PerformCommand method, in connection.Open()
    PerformCommand(_historyRepository.GetCreateIfNotExistsScript(), connection.ConnectionString);

    var commandLists = GetMigrationCommandLists(_historyRepository.GetAppliedMigrations(), null);

    foreach (var commandList in commandLists)
    {
        var commands = commandList();

        foreach (var command in commands)
        {
            Console.WriteLine($"Migration SQL: {command.CommandText.Substring(0, command.CommandText.Length <= 100 ? command.CommandText.Length : 100)}");
            PerformCommand(command.CommandText, connection.ConnectionString);
        }
    }
}

public void PerformCommand(string sql, string connectionString)
{
    using (var connection = new SqlConnection(connectionString))
    {
        connection.Open(); 
        //Above call fails randomly right after db on azure is created. SqlException Login failed for user 'admin', number 18456
        //If it not fails after CREATE DATABASE, everything works fine.

        var command = new SqlCommand(sql, connection)
        command.ExecuteNonQuery();
        connection.Close();
    }
}                

After Azure database is created using CREATE DATABASE, connection.Open() fails from time to time. I suppose, that there is needed a time gap after everything is done on Azure site (I don't know, meybe some configuration is performing in the background). If I add Thread.Sleep(2 * 60 * 1000) right after masterDbContext.Database.ExecuteSqlCommand(new RawSqlString(createSql)) no issue occures.

Please remember, that we are talking about connection to Azure SQL Server.

Here is my connectionString: Server=tcp:myazuredbserver.database.windows.net,1433;Initial Catalog=myDatabase;Persist Security Info=False;User ID=myUserId;Password=myPassword;MultipleActiveResultSets=False;Encrypt=True;TrustServerCertificate=False;Connection Timeout=240;

[ajcvickers]

Note for triage: looks like we need to review which error numbers can indicate that the database doesn't exist. We could also expose the amount of time to wait until Exists returns true.

[ajcvickers]

Note from triage: we are still following up with the SQL Server folks on this.

[Arcanst]

Hey, is there a real possibility that this will be implemented anytime soon? I'm another developer on this project and we're about to switch to core3.0 - I'm just wondering if our custom migrators should be removed or they are still necessary.

[AndriySvyryd]

@Arcanst It's still not clear what is the right fix for this

[AndriySvyryd]

We got confirmation that retrying on 18456 in RetryOnExistsFailure is the correct fix.